search

chrishobcroft / TestingTheMerge

Repo containing notes for testing the merge.
The Unlicense
7 stars 5 forks source link

ERROR - Execution Client is offline #4

Closed fdimeglio closed 2 years ago

fdimeglio commented 2 years ago

Hello,

I have followed your very cool minimalistic guide steps by steps and everything is fine except the following when running Teku:

/run-teku.sh 2022-03-11 11:50:22,685 main INFO Configuring logging for destination: console 2022-03-11 11:50:22,687 main INFO Logging includes events: true 2022-03-11 11:50:22,687 main INFO Logging includes validator duties: true 2022-03-11 11:50:22,687 main INFO Logging includes color: true 2022-03-11 11:50:22,697 main INFO Include P2P warnings set to: false 2022-03-11 11:50:23.012 INFO - Teku version: teku/v22.3.0+56-g216f8d9/linux-x86_64/-ubuntu-openjdk64bitservervm-java-11 2022-03-11 11:50:23.014 INFO - This software is licensed under the Apache License, Version 2.0 (the "License"); you may not use this software except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 2022-03-11 11:50:23.165 INFO - Using default implementation for ThreadExecutor 2022-03-11 11:50:23.167 INFO - Job execution threads will use class loader of thread: main 2022-03-11 11:50:23.173 INFO - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl 2022-03-11 11:50:23.174 INFO - Quartz Scheduler v.2.3.2 created. 2022-03-11 11:50:23.174 INFO - RAMJobStore initialized. 2022-03-11 11:50:23.174 INFO - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler' with instanceId 'NON_CLUSTERED' Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally. NOT STARTED. Currently in standby mode. Number of jobs executed: 0 Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads. Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2022-03-11 11:50:23.174 INFO - Quartz scheduler 'DefaultQuartzScheduler' initialized from default resource file in Quartz package: 'quartz.properties' 2022-03-11 11:50:23.174 INFO - Quartz scheduler version: 2.3.2 2022-03-11 11:50:23.209 INFO - validator-api-enabled is false, not starting rest api. 2022-03-11 11:50:23.211 INFO - Storing beacon chain data in: /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon 2022-03-11 11:50:23.240 INFO - Using optimized BLST library 2022-03-11 11:50:23.246 INFO - Beacon data directory set to: /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon 2022-03-11 11:50:23.303 INFO - BLS: loaded BLST library 2022-03-11 11:50:23.305 INFO - Loading 1 validator keys... 2022-03-11 11:50:23.330 INFO - Created leveldb_tree Hot and Finalized database (leveldb-tree) at /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon/db 2022-03-11 11:50:23.351 INFO - Using execution engine at http://localhost:8551 2022-03-11 11:50:23.352 INFO - Execution Engine version: KILNV2 2022-03-11 11:50:23.384 INFO - Initializing storage 2022-03-11 11:50:24.355 INFO - Loaded 1 Validators: a551e3c 2022-03-11 11:50:24.364 INFO - Storage initialization complete 2022-03-11 11:50:25.582 INFO - Completed regeneration of block 0x8839f7e752773e637eebed1564bfb1677f01c2198c6cc50a2e0bbe460f756dc5 at slot 1600 by replaying 32 blocks. Took 1196ms 2022-03-11 11:50:25.831 INFO - Loading generated p2p private key from: generated-node-key 2022-03-11 11:50:26.080 INFO - PreGenesis Local ENR: enr:-Iu4QAJOcI40nxfvU0eLI4t3UIPEHtNIPfd_ZdGVUF1ORxeWUD8frAIC8-9nCfXKJ-9hkvnTeQ6ytg24lz5cYKTMF5QUhGV0aDKQes1pqXAAAGn__4JpZIJ2NIlzZWNwMjU2azGhAj-oBgxwhrVmXYIyZbfn1UFW0LpyEV4I5uFk0lWOose 2022-03-11 11:50:26.086 INFO - Using multipeer sync 2022-03-11 11:50:26.118 INFO - rest-api-enabled is false, not starting rest api. 2022-03-11 11:50:26.251 INFO - Starting libp2p network... 2022-03-11 11:50:26.295 INFO - Listening for connections on: /ip4/127.0.1.1/tcp/9000/p2p/16Uiu2HAkyiAGNmUmNtXhf2UDUHds6Mrvib9hru5CqediFGnKgV5o 2022-03-11 11:50:26.297 INFO - Starting discovery server on UDP port 9000 2022-03-11 11:50:26.313 INFO - UDP discovery client started 2022-03-11 11:50:26.314 INFO - Monitor has started. Waiting BELLATRIX fork activation. Polling every PT14S 2022-03-11 11:50:26.323 INFO - Scheduler DefaultQuartzScheduler$_NON_CLUSTERED started. 2022-03-11 11:50:26.428 INFO - Syncing Target slot: 1727, Head slot: 1639, Remaining slots: 88, Connected peers: 0 2022-03-11 11:50:26.440 INFO - Local ENR: enr:-Iu4QBl7irUfOTwmMahhrhw7oeS2f2kNAiEbjQR6tJlrj1S1GBzqknVVeeZTnyEmPXRj7ApLMCpLSzjr2pMXFaBXMJYVhGV0aDKQRO38rXAAAHGWAAAAAAAAAIJpZIJ2NIlzZWNwMjU2azGhAj-oBgxwhrVmXYIyZbfn1UFW0LpyEV4I_5uFk0lWOose 2022-03-11 11:50:26.441 INFO - Starting eth2 gossip 2022-03-11 11:50:26.825 INFO - Epoch Event Epoch: 54, Justified checkpoint: 50, Finalized checkpoint: 49, Finalized root: ab88f02038ae4933284829fdf3a9adc1efac5989157195eb63e4c6d40c62fce9 2022-03-11 11:50:27.072 INFO - Completed regeneration of block 0x0bb174639100bce1685c0c59c26e556afe060a0dcebffccf0c40793a67eb28da at slot 1639 by replaying 37 blocks. Took 1362ms 2022-03-11 11:50:36.008 WARN - Validator Slashing protection not loaded for validators: a551e3c 2022-03-11 11:50:36.338 INFO - Syncing Target slot: 1728, Head slot: 1639, Remaining slots: 89, Connected peers: 0 2022-03-11 11:50:40.379 ERROR - Execution Client is offline java.lang.Error: -32000: invalid ttd: EL 20000000000000 CL 0xe8d4a51000 at tech.pegasys.teku.ethereum.executionlayer.client.Web3JExecutionEngineClient.lambda$doRequest$3(Web3JExecutionEngineClient.java:211) ~[teku-ethereum-executionlayer-develop.jar:22.3.0+56-g216f8d9] at java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930) ~[?:?] at java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] at org.web3j.utils.Async.lambda$run$1(Async.java:38) ~[core-4.9.0.jar:?] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?] at java.lang.Thread.run(Thread.java:829) ~[?:?] 2022-03-11 11:50:40.382 ERROR - an error occurred while querying remote transition configuration java.util.concurrent.CompletionException: java.lang.IllegalArgumentException: Invalid remote response: -32000: invalid ttd: EL 20000000000000 CL 0xe8d4a51000 at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314) ~[?:?] at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319) ~[?:?] at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:645) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:147) ~[teku-infrastructure-async-develop.jar:22.3.0+56-g216f8d9] at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) ~[?:?] at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) ~[?:?] at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?] at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073) ~[?:?] at org.web3j.utils.Async.lambda$run$1(Async.java:38) ~[core-4.9.0.jar:?] at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?] at java.lang.Thread.run(Thread.java:829) ~[?:?] Caused by: java.lang.IllegalArgumentException: Invalid remote response: -32000: invalid ttd: EL 20000000000000 CL 0xe8d4a51000 at com.google.common.base.Preconditions.checkArgument(Preconditions.java:220) ~[guava-31.1-jre.jar:?] at tech.pegasys.teku.ethereum.executionlayer.ExecutionEngineChannelImpl.unwrapResponseOrThrow(ExecutionEngineChannelImpl.java:100) ~[teku-ethereum-executionlayer-develop.jar:22.3.0+56-g216f8d9] at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642) ~[?:?] ... 12 more

Any idea about what is going on here ?

Thx.

===

I am using for "run-teku.sh" the following from your guide:

./teku/build/install/teku/bin/teku \ --data-path "datadir-teku" \ --network kiln \ --ee-endpoint http://localhost:8551 \ --Xee-version kilnv2 \ --ee-jwt-secret-file "/tmp/jwtsecret" \ --log-destination console \ --validator-keys /home/fdimeglio/Downloads/TestingTheMerge/staking_deposit-cli-e2a7c94-linux-amd64/validator_keys:/home/fdimeglio/Downloads/TestingTheMerge/staking_deposit-cli-e2a7c94-linux-amd64/validator_keys \ --validators-proposer-default-fee-recipient 0xb1B9CCe8F0BCB9046A605E9612fB8D2A97Eea77a \ --p2p-discovery-bootnodes "enr:-Iq4QMCTfIMXnow27baRUb35Q8iiFHSIDBJh6hQM5Axohhf4b6Kr_cOCu0htQ5WvVqKvFgY28893DHAg8gnBAXsAVqmGAX53x8JggmlkgnY0gmlwhLKAlv6Jc2VjcDI1NmsxoQK6S-Cii_KmfFdUJL2TANL3ksaKUnNXvTCv1tLwXs0QgIN1ZHCCIyk,enr:-Iq4QMCTfIMXnow27baRUb35Q8iiFHSIDBJh6hQM5Axohhf4b6Kr_cOCu0htQ5WvVqKvFgY28893DHAg8gnBAXsAVqmGAX53x8JggmlkgnY0gmlwhLKAlv6Jc2VjcDI1NmsxoQK6S-Cii_KmfFdUJL2TANL3ksaKUnNXvTCv1tLwXs0QgIN1ZHCCIyk,enr:-KG4QFkPJUFWuONp5grM94OJvNht9wX6N36sA4wqucm6Z02ECWBQRmh6AzndaLVGYBHWre67mjK-E0uKt2CIbWrsZ_8DhGV0aDKQc6pfXHAAAHAyAAAAAAAAAIJpZIJ2NIJpcISl6LTmiXNlY3AyNTZrMaEDHlSNOgYrNWP8_l_WXqDMRvjv6gUAvHKizfqDDVc8feaDdGNwgiMog3VkcIIjKA,enr:-MK4QI-wkVW1PxL4ksUM4H_hMgTTwxKMzvvDMfoiwPBuRxcsGkrGPLo4Kho3Ri1DEtJG4B6pjXddbzA9iF2gVctxv42GAX9v5WG5h2F0dG5ldHOIAAAAAAAAAACEZXRoMpBzql9ccAAAcDIAAAAAAAAAgmlkgnY0gmlwhKRcjMiJc2VjcDI1NmsxoQK1fc46pmVHKq8HNYLkSVaUv4uK2UBsGgjjGWU6AAhAY4hzeW5jbmV0cwCDdGNwgiMog3VkcIIjKA"

chrishobcroft commented 2 years ago

Can I ask, do you have Geth running when you launch Teku?

(note, Geth is an example of an "Execution Client", while Teku is a "Consensus Client")

fdimeglio commented 2 years ago

Yes I do, see the following Geth logs. Do you mean that we should run only Geth or run only Teku?

~/Downloads/TestingTheMerge$ ./geth-run.sh INFO [03-11|09:30:36.598] Maximum peer count ETH=50 LES=0 total=50 INFO [03-11|09:30:36.598] Smartcard socket not found, disabling err="stat /run/pcscd/pcscd.comm: no such file or directory" INFO [03-11|09:30:36.598] Set global gas cap cap=50,000,000 INFO [03-11|09:30:36.598] Allocated trie memory caches clean=154.00MiB dirty=256.00MiB INFO [03-11|09:30:36.598] Allocated cache and file handles database=/home/fdimeglio/Downloads/TestingTheMerge/geth-datadir/geth/chaindata cache=512.00MiB handles=524,288 INFO [03-11|09:30:36.634] Opened ancient database database=/home/fdimeglio/Downloads/TestingTheMerge/geth-datadir/geth/chaindata/ancient readonly=false INFO [03-11|09:30:36.634] Initialised chain configuration config="{ChainID: 1337802 Homestead: 0 DAO: DAOSupport: false EIP150: 0 EIP155: 0 EIP158: 0 Byzantium: 0 Constantinople: 0 Petersburg: 0 Istanbul: 0, Muir Glacier: , Berlin: 0, London: 0, Arrow Glacier: , MergeFork: 1000, Terminal TD: 20000000000000, Engine: unknown}" INFO [03-11|09:30:36.634] Disk storage enabled for ethash caches dir=/home/fdimeglio/Downloads/TestingTheMerge/geth-datadir/geth/ethash count=3 INFO [03-11|09:30:36.634] Disk storage enabled for ethash DAGs dir=/home/fdimeglio/.ethash count=2 INFO [03-11|09:30:36.634] Initialising Ethereum protocol network=1,337,802 dbversion= INFO [03-11|09:30:36.634] Loaded most recent local header number=0 hash=51c7fe..4dd4f8 td=1 age=52y11mo1w INFO [03-11|09:30:36.634] Loaded most recent local full block number=0 hash=51c7fe..4dd4f8 td=1 age=52y11mo1w INFO [03-11|09:30:36.634] Loaded most recent local fast block number=0 hash=51c7fe..4dd4f8 td=1 age=52y11mo1w WARN [03-11|09:30:36.634] Failed to load snapshot, regenerating err="missing or corrupted snapshot" INFO [03-11|09:30:36.635] Rebuilding state snapshot INFO [03-11|09:30:36.635] Regenerated local transaction journal transactions=0 accounts=0 INFO [03-11|09:30:36.635] Resuming state snapshot generation root=52e628..4bee62 accounts=0 slots=0 storage=0.00B elapsed="167.784µs" INFO [03-11|09:30:36.635] Gasprice oracle is ignoring threshold set threshold=2 WARN [03-11|09:30:36.635] Error reading unclean shutdown markers error="leveldb: not found" WARN [03-11|09:30:36.635] Catalyst mode enabled protocol=eth INFO [03-11|09:30:36.635] Starting peer-to-peer node instance=Geth/v1.10.17-unstable-b951e9cb-20220311/linux-amd64/go1.17.8 INFO [03-11|09:30:36.641] Generated state snapshot accounts=268 slots=31 storage=13.09KiB elapsed=6.356ms INFO [03-11|09:30:36.650] New local node record seq=1,647,019,836,650 id=6c18fa50438a4e7d ip=127.0.0.1 udp=30303 tcp=30303 INFO [03-11|09:30:36.651] Started P2P networking self=enode://7ae13d61c86cc1fac7ba37801214ba167bafb846211bafe0de1c74f6da76ac14a8927c23f3f2a3af457e69960d5f253f2e41df3886db1bc4bc7a126ba873e22c@127.0.0.1:30303 INFO [03-11|09:30:36.652] IPC endpoint opened url=/home/fdimeglio/Downloads/TestingTheMerge/geth-datadir/geth.ipc INFO [03-11|09:30:36.653] HTTP server started endpoint=127.0.0.1:8545 auth=false prefix= cors=* vhosts=localhost INFO [03-11|09:30:36.653] WebSocket enabled url=ws://127.0.0.1:8551 INFO [03-11|09:30:36.653] HTTP server started endpoint=127.0.0.1:8551 auth=true prefix= cors=localhost vhosts=localhost INFO [03-11|09:30:38.120] New local node record seq=1,647,019,836,651 id=6c18fa50438a4e7d ip=76.244.43.95 udp=30303 tcp=30303 INFO [03-11|09:30:46.654] Block synchronisation started INFO [03-11|09:30:49.693] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=580.00B throttle=8192 INFO [03-11|09:30:50.232] Imported new chain segment blocks=192 txs=0 mgas=0.000 elapsed=537.715ms mgasps=0.000 number=192 hash=c2add1..468455 age=2d5h11m dirty=209.60KiB INFO [03-11|09:30:50.624] Imported new chain segment blocks=1297 txs=0 mgas=0.000 elapsed=388.865ms mgasps=0.000 number=1489 hash=05d599..5e59ed age=2d3h23m dirty=209.25KiB INFO [03-11|09:30:50.640] Imported new chain segment blocks=24 txs=1 mgas=0.075 elapsed=15.843ms mgasps=4.743 number=1513 hash=b77a5f..a82626 age=2d3h23m dirty=209.51KiB INFO [03-11|09:30:50.698] New local node record seq=1,647,019,836,652 id=6c18fa50438a4e7d ip=76.244.43.95 udp=30303 tcp=30303 INFO [03-11|09:30:50.808] Imported new chain segment blocks=49 txs=1105 mgas=48.836 elapsed=105.288ms mgasps=463.829 number=1562 hash=c4b3fc..9a2612 age=2d3h19m dirty=781.33KiB INFO [03-11|09:30:50.914] Imported new chain segment blocks=26 txs=1300 mgas=75.407 elapsed=105.111ms mgasps=717.396 number=1588 hash=646b18..9136ff age=2d3h16m dirty=1.52MiB INFO [03-11|09:30:50.990] Imported new chain segment blocks=18 txs=900 mgas=52.904 elapsed=75.832ms mgasps=697.652 number=1606 hash=11f1c4..df2589 age=2d3h14m dirty=2.06MiB INFO [03-11|09:30:51.056] Imported new chain segment blocks=16 txs=800 mgas=46.877 elapsed=65.522ms mgasps=715.442 number=1622 hash=9127eb..fc50a3 age=2d3h12m dirty=2.57MiB INFO [03-11|09:30:52.649] Imported new chain segment blocks=2048 txs=10800 mgas=634.269 elapsed=1.383s mgasps=458.506 number=3670 hash=f2208b..8f5854 age=1d22h28m dirty=1.07MiB INFO [03-11|09:30:53.617] Imported new chain segment blocks=2048 txs=34 mgas=4.595 elapsed=962.310ms mgasps=4.775 number=5718 hash=a342f3..41dbcc age=1d18h36m dirty=1.12MiB INFO [03-11|09:30:54.404] Imported new chain segment blocks=2048 txs=583 mgas=23.342 elapsed=776.698ms mgasps=30.053 number=7766 hash=aa09d3..7188d2 age=1d15h25m dirty=1.34MiB INFO [03-11|09:30:55.438] Imported new chain segment blocks=2048 txs=687 mgas=63.563 elapsed=1.022s mgasps=62.139 number=9814 hash=5801a7..a05491 age=1d13h5m dirty=1.55MiB INFO [03-11|09:30:56.510] Imported new chain segment blocks=2048 txs=1676 mgas=59.517 elapsed=1.060s mgasps=56.101 number=11862 hash=cc2360..11fde8 age=1d9h40m dirty=2.29MiB INFO [03-11|09:30:58.775] Imported new chain segment blocks=2048 txs=6695 mgas=254.831 elapsed=2.253s mgasps=113.086 number=13910 hash=aaeeb9..ff85ff age=1d4h20m dirty=4.69MiB INFO [03-11|09:31:02.823] Imported new chain segment blocks=2048 txs=4454 mgas=200.063 elapsed=4.035s mgasps=49.573 number=15958 hash=203533..10d81f age=23h31m11s dirty=4.15MiB INFO [03-11|09:31:06.002] Imported new chain segment blocks=2048 txs=932 mgas=55.043 elapsed=3.168s mgasps=17.372 number=18006 hash=821e13..fce3a6 age=22h25m17s dirty=4.23MiB INFO [03-11|09:31:08.208] Imported new chain segment blocks=2048 txs=4571 mgas=138.393 elapsed=2.193s mgasps=63.100 number=20054 hash=072f67..65e0f3 age=13h14m53s dirty=7.04MiB INFO [03-11|09:31:13.135] Imported new chain segment blocks=1296 txs=30299 mgas=3062.419 elapsed=4.919s mgasps=622.544 number=21350 hash=767200..c8879e age=6h11m3s dirty=9.23MiB INFO [03-11|09:31:21.082] Imported new chain segment blocks=1551 txs=40630 mgas=4696.317 elapsed=7.936s mgasps=591.752 number=22901 hash=d8653c..1e0f1c age=5h13m28s dirty=10.69MiB INFO [03-11|09:31:24.498] Imported new chain segment blocks=2048 txs=13252 mgas=1328.705 elapsed=3.405s mgasps=390.192 number=24949 hash=c28be6..f0bf67 age=2h26m7s dirty=9.28MiB INFO [03-11|09:31:25.546] Imported new chain segment blocks=1098 txs=2004 mgas=73.176 elapsed=1.041s mgasps=70.252 number=26047 hash=d0318c..b952ee age=2m34s dirty=8.78MiB INFO [03-11|09:31:27.073] Imported new chain segment blocks=2 txs=12 mgas=0.378 elapsed=6.999ms mgasps=54.067 number=26049 hash=644728..6c34c5 age=1m52s dirty=8.81MiB ERROR[03-11|09:32:15.206] Snapshot extension registration failed peer=1125cc47 err="peer connected on snap without compatible eth support" ERROR[03-11|09:32:19.800] Snapshot extension registration failed peer=1dea0443 err="peer connected on snap without compatible eth support" ERROR[03-11|09:32:21.957] Snapshot extension registration failed peer=1d4fc8e3 err="peer connected on snap without compatible eth support" ERROR[03-11|09:32:28.538] Snapshot extension registration failed peer=2ee92e22 err="peer connected on snap without compatible eth support" ERROR[03-11|09:33:17.943] Snapshot extension registration failed peer=1125cc47 err="peer connected on snap without compatible eth support" INFO [03-11|09:33:19.898] Imported new chain segment blocks=1 txs=11 mgas=0.308 elapsed=6.335ms mgasps=48.588 number=26050 hash=a5515c..b4e7b5 age=2m25s dirty=8.84MiB INFO [03-11|09:34:03.182] Imported new chain segment blocks=1 txs=6 mgas=0.172 elapsed=3.331ms mgasps=51.663 number=26051 hash=54ee5e..3351e0 dirty=8.85MiB ERROR[03-11|09:34:22.250] Snapshot extension registration failed peer=a79a44f5 err="peer connected on snap without compatible eth support" INFO [03-11|09:36:32.430] Imported new chain segment blocks=1 txs=13 mgas=0.379 elapsed=3.986ms mgasps=95.176 number=26052 hash=093283..4c6ada age=2m30s dirty=8.88MiB INFO [03-11|09:37:31.212] Imported new chain segment blocks=1 txs=6 mgas=0.172 elapsed=3.681ms mgasps=46.754 number=26053 hash=745dfc..a3d677 dirty=8.90MiB INFO [03-11|09:38:15.064] Imported new chain segment blocks=1 txs=4 mgas=0.115 elapsed=3.412ms mgasps=33.624 number=26054 hash=fc48a5..44377d dirty=8.91MiB INFO [03-11|09:38:20.583] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=5.005ms mgasps=0.000 number=26055 hash=ace549..ca9a15 dirty=8.91MiB INFO [03-11|09:38:53.138] Imported new chain segment blocks=1 txs=2 mgas=0.057 elapsed=18.326ms mgasps=3.130 number=26056 hash=0c52b5..a89aba dirty=8.92MiB INFO [03-11|09:39:55.233] Imported new chain segment blocks=1 txs=10 mgas=0.287 elapsed=3.681ms mgasps=77.925 number=26057 hash=a4ca91..2d5ef9 age=1m2s dirty=8.94MiB INFO [03-11|09:40:05.753] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=2.397ms mgasps=0.000 number=26058 hash=27824e..075506 dirty=8.94MiB INFO [03-11|09:42:26.495] Imported new chain segment blocks=1 txs=13 mgas=0.387 elapsed=4.142ms mgasps=93.360 number=26059 hash=9a1245..aa54e9 age=2m20s dirty=8.97MiB INFO [03-11|09:43:30.500] Imported new chain segment blocks=1 txs=12 mgas=0.361 elapsed=2.404ms mgasps=150.294 number=26060 hash=f3c88e..5df01c age=1m4s dirty=8.99MiB INFO [03-11|09:44:58.905] Imported new chain segment blocks=1 txs=12 mgas=0.391 elapsed=4.380ms mgasps=89.282 number=26061 hash=75f18a..22f646 age=1m28s dirty=9.02MiB INFO [03-11|09:46:50.617] Imported new chain segment blocks=1 txs=6 mgas=0.189 elapsed=3.716ms mgasps=50.912 number=26062 hash=523fce..82ca5f age=1m52s dirty=9.04MiB INFO [03-11|09:46:55.289] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=2.529ms mgasps=0.000 number=26063 hash=48bed3..ac5b71 dirty=9.04MiB

INFO [03-11|09:48:49.302] Imported new chain segment blocks=1 txs=10 mgas=0.287 elapsed=2.925ms mgasps=98.036 number=26064 hash=e9b4c9..55743c age=1m54s dirty=9.06MiB INFO [03-11|09:48:49.893] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=4.955ms mgasps=0.000 number=26065 hash=ca9753..068958 dirty=9.06MiB INFO [03-11|09:49:14.992] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=4.467ms mgasps=0.000 number=26066 hash=9d74f0..c13831 dirty=9.06MiB INFO [03-11|09:49:35.746] Imported new chain segment blocks=1 txs=8 mgas=0.229 elapsed=6.089ms mgasps=37.683 number=26067 hash=bb9b11..856a09 dirty=9.08MiB INFO [03-11|09:50:02.525] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=2.517ms mgasps=0.000 number=26068 hash=489c9c..d0fcbc dirty=9.08MiB INFO [03-11|09:50:47.784] Imported new chain segment blocks=1 txs=8 mgas=0.229 elapsed=3.704ms mgasps=61.949 number=26069 hash=f94524..3b897a dirty=9.10MiB INFO [03-11|09:51:25.194] Imported new chain segment blocks=1 txs=2 mgas=0.057 elapsed=5.504ms mgasps=10.422 number=26070 hash=b593bd..740d1d dirty=9.11MiB INFO [03-11|09:53:35.894] Imported new chain segment blocks=1 txs=12 mgas=0.344 elapsed=6.668ms mgasps=51.618 number=26071 hash=f18b6a..406d09 age=2m11s dirty=9.13MiB INFO [03-11|09:54:39.528] Imported new chain segment blocks=1 txs=6 mgas=0.172 elapsed=3.381ms mgasps=50.902 number=26072 hash=328265..262a66 age=1m4s dirty=9.14MiB INFO [03-11|09:54:39.725] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=2.632ms mgasps=0.000 number=26073 hash=774130..e364a0 dirty=9.14MiB INFO [03-11|09:54:44.383] Imported new chain segment blocks=1 txs=0 mgas=0.000 elapsed=2.624ms mgasps=0.000 number=26074 hash=c1d2bd..72bd55 dirty=9.14MiB WARN [03-11|09:55:52.134] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=0 duration="79.91µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:56:06.079] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=1 duration="58.229µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:56:20.079] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=2 duration="55.023µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:56:34.079] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=3 duration="50.896µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:56:48.080] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=4 duration="63.85µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:57:02.080] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=5 duration="53.41µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:57:16.080] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=6 duration="55.894µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:57:30.080] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=7 duration="58.019µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:57:44.081] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=8 duration="58.109µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:57:58.081] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=9 duration="62.577µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:58:12.080] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=10 duration="52.959µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:58:26.081] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=11 duration="52.328µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:58:40.081] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=12 duration="54.552µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:58:54.081] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=13 duration="41.158µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:59:08.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=14 duration="73.437µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:59:22.083] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=15 duration="53.3µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:59:36.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=16 duration="55.544µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|09:59:50.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=17 duration="54.462µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|10:00:04.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=18 duration="51.807µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|10:00:18.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=19 duration="52.849µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|10:00:32.082] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=20 duration="68.418µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" WARN [03-11|10:00:46.083] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=21 duration="45.786µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000" INFO [03-11|10:00:51.511] Imported new chain segment blocks=1 txs=12 mgas=0.344 elapsed=6.247ms mgasps=55.090 number=26075 hash=9d5889..fe924e age=6m8s dirty=9.17MiB

fdimeglio commented 2 years ago

Please note also the Geth log, which seems to be related to Teku:

WARN [03-11|10:00:46.083] Served engine_exchangeTransitionConfigurationV1 conn=127.0.0.1:37806 reqid=21 duration="45.786µs" err="invalid ttd: EL 20000000000000 CL 0xe8d4a51000"

chrishobcroft commented 2 years ago

It seems your issues are related to the network configuration change that was made earlier.

Your best nest now is to delete the merge-testnets folder and start again. Shouldn't take long.

chrishobcroft commented 2 years ago

For reference, the issue that you correctly identified, was the mismatch between Geth and Teku ref the ttd. There was a bug in Teku's implementation which failed to override the config when using the --Xnetwork-total-terminal-difficulty-override flag. This is now fixed, and a rebuild would pick up the updated code.

I will perhaps add a section about updating the code using git pull

fdimeglio commented 2 years ago

Thank you for the confirmation Chris. This is quite strange as I did my git clone about 2h ago and I did also a git pull half an hour after to check if there was any new commit.

Would you please let us know which commit we should have ?

Thx

fdimeglio commented 2 years ago

Also, I can see that you added in the Teku command line this:

--Xnetwork-total-terminal-difficulty-override=20000000000000

which indeed, after doing also a full clean/rebuild lead to no more error in the Teku log:

$ ./run-teku.sh 2022-03-11 14:18:27,152 main INFO Configuring logging for destination: console 2022-03-11 14:18:27,154 main INFO Logging includes events: true 2022-03-11 14:18:27,154 main INFO Logging includes validator duties: true 2022-03-11 14:18:27,154 main INFO Logging includes color: true 2022-03-11 14:18:27,164 main INFO Include P2P warnings set to: false 2022-03-11 14:18:27.476 INFO - Teku version: teku/v22.3.0+56-g216f8d9/linux-x86_64/-ubuntu-openjdk64bitservervm-java-11 2022-03-11 14:18:27.479 INFO - This software is licensed under the Apache License, Version 2.0 (the "License"); you may not use this software except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 2022-03-11 14:18:27.480 WARN - Bellatrix parameter TERMINAL_TOTAL_DIFFICULTY has been overridden to 0x000000000000000000000000000000000000000000000000000012309ce54000 2022-03-11 14:18:27.651 INFO - Using default implementation for ThreadExecutor 2022-03-11 14:18:27.653 INFO - Job execution threads will use class loader of thread: main 2022-03-11 14:18:27.660 INFO - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl 2022-03-11 14:18:27.660 INFO - Quartz Scheduler v.2.3.2 created. 2022-03-11 14:18:27.661 INFO - RAMJobStore initialized. 2022-03-11 14:18:27.661 INFO - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler' with instanceId 'NON_CLUSTERED' Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally. NOT STARTED. Currently in standby mode. Number of jobs executed: 0 Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads. Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

2022-03-11 14:18:27.661 INFO - Quartz scheduler 'DefaultQuartzScheduler' initialized from default resource file in Quartz package: 'quartz.properties' 2022-03-11 14:18:27.661 INFO - Quartz scheduler version: 2.3.2 2022-03-11 14:18:27.687 INFO - validator-api-enabled is false, not starting rest api. 2022-03-11 14:18:27.689 INFO - Storing beacon chain data in: /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon 2022-03-11 14:18:27.716 INFO - Using optimized BLST library 2022-03-11 14:18:27.726 INFO - Beacon data directory set to: /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon 2022-03-11 14:18:27.758 INFO - BLS: loaded BLST library 2022-03-11 14:18:27.761 INFO - Loading 1 validator keys... 2022-03-11 14:18:27.772 INFO - Created leveldb_tree Hot and Finalized database (leveldb-tree) at /home/fdimeglio/Downloads/TestingTheMerge/datadir-teku/beacon/db 2022-03-11 14:18:27.801 INFO - Using execution engine at http://localhost:8551 2022-03-11 14:18:27.803 INFO - Execution Engine version: KILNV2 2022-03-11 14:18:27.842 INFO - Initializing storage 2022-03-11 14:18:28.705 INFO - Loaded 1 Validators: a551e3c 2022-03-11 14:18:28.720 INFO - Storage initialization complete 2022-03-11 14:18:29.905 INFO - Completed regeneration of block 0x8839f7e752773e637eebed1564bfb1677f01c2198c6cc50a2e0bbe460f756dc5 at slot 1600 by replaying 32 blocks. Took 1166ms 2022-03-11 14:18:30.185 INFO - Loading generated p2p private key from: generated-node-key 2022-03-11 14:18:30.398 INFO - PreGenesis Local ENR: enr:-Iu4QBmJgIdhEYhzX_K91EAc_I7UI1M-GD362hT7Y1qIpK0LIIB3rCuivoLodtJK7AhL5OfBp7DA_2N7tZGWkz_20FUYhGV0aDKQes1pqXAAAGn__4JpZIJ2NIlzZWNwMjU2azGhAj-oBgxwhrVmXYIyZbfn1UFW0LpyEV4I5uFk0lWOose 2022-03-11 14:18:30.404 INFO - Using multipeer sync 2022-03-11 14:18:30.460 INFO - rest-api-enabled is false, not starting rest api. 2022-03-11 14:18:30.473 INFO - Starting libp2p network... 2022-03-11 14:18:30.517 INFO - Listening for connections on: /ip4/127.0.1.1/tcp/9000/p2p/16Uiu2HAkyiAGNmUmNtXhf2UDUHds6Mrvib9hru5CqediFGnKgV5o 2022-03-11 14:18:30.517 INFO - Starting discovery server on UDP port 9000 2022-03-11 14:18:30.532 INFO - Monitor has started. Waiting BELLATRIX fork activation. Polling every PT14S 2022-03-11 14:18:30.534 INFO - UDP discovery client started 2022-03-11 14:18:30.539 INFO - Scheduler DefaultQuartzScheduler$_NON_CLUSTERED started. 2022-03-11 14:18:30.650 INFO - Syncing Target slot: 2467, Head slot: 1654, Remaining slots: 813, Connected peers: 0 2022-03-11 14:18:30.661 INFO - Local ENR: enr:-Iu4QO9J1JNVPrYCv8WTP9BjMaplvr-0QGNM1hlsQaJ-GvKRFE1Aff1Q3I_s2Ok9VAzYNdSKhVe5SysmKiMLFBOKDesZhGV0aDKQRO38rXAAAHGWAAAAAAAAAIJpZIJ2NIlzZWNwMjU2azGhAj-oBgxwhrVmXYIyZbfn1UFW0LpyEV4I_5uFk0lWOose 2022-03-11 14:18:32.014 INFO - Completed regeneration of block 0x5e8e1f22b7b6793ba85ec2ccaaae063f5d3f4c5eed341ca1291de259713bd1eb at slot 1654 by replaying 50 blocks. Took 1985ms 2022-03-11 14:18:36.008 WARN - Validator Slashing protection not loaded for validators: a551e3c 2022-03-11 14:18:36.051 INFO - Syncing Target slot: 2468, Head slot: 1654, Remaining slots: 814, Connected peers: 0 2022-03-11 14:18:48.048 INFO - Syncing Target slot: 2469, Head slot: 1654, Remaining slots: 815, Connected peers: 0 2022-03-11 14:19:00.047 INFO - Syncing Target slot: 2470, Head slot: 1654, Remaining slots: 816, Connected peers: 0 2022-03-11 14:19:12.048 INFO - Syncing Target slot: 2471, Head slot: 1654, Remaining slots: 817, Connected peers: 0 2022-03-11 14:19:12.122 INFO - Syncing started 2022-03-11 14:19:23.036 INFO - Completed regeneration of block 0x4418aa1d33de7cf09d1f9feebaa3a7b98b2d84dbbf086496db9081a45596aaf2 at slot 1632 by replaying 31 blocks. Took 938ms 2022-03-11 14:19:24.532 INFO - Syncing Target slot: 2472, Head slot: 1702, Remaining slots: 770, Connected peers: 2 2022-03-11 14:19:36.113 INFO - Syncing Target slot: 2473, Head slot: 1758, Remaining slots: 715, Connected peers: 2 2022-03-11 14:19:48.129 INFO - Syncing Target slot: 2474, Head slot: 1887, Remaining slots: 587, Connected peers: 3 2022-03-11 14:20:00.104 INFO - Syncing Target slot: 2475, Head slot: 2172, Remaining slots: 303, Connected peers: 3 2022-03-11 14:20:12.141 INFO - Syncing Target slot: 2476, Head slot: 2441, Remaining slots: 35, Connected peers: 3 2022-03-11 14:20:13.461 INFO - Syncing completed 2022-03-11 14:20:13.461 INFO - Starting eth2 gossip 2022-03-11 14:20:24.156 INFO - Syncing Target slot: 2477, Head slot: 2473, Remaining slots: 4, Connected peers: 2 2022-03-11 14:20:30.562 WARN - Unable to retrieve status for validator a551e3c. 2022-03-11 14:20:40.060 INFO - Slot Event Slot: 2478, Block: ff3d1a2e491305b176e34b3b038a48aadaa90928d927cf3d1dc229c564df3f70, Justified: 76, Finalized: 75, Peers: 2 2022-03-11 14:20:52.050 INFO - Slot Event Slot: 2479, Block: 2c942c0c572e98a40d49a05389b2a63390885328f7003e352e544e5e3b70e085, Justified: 76, Finalized: 75, Peers: 2 2022-03-11 14:21:04.050 INFO - Slot Event *** Slot: 2480, Block: 64762a110919f702b7e12b39d801eebf8c293f66be0964d800e8cd85953a9545, Justified: 76, Finalized: 75, Peers: 2