Bug: keymanager API not started when engine API not yet up

yorickdowne commented 1 year ago

Description

Teku 23.9.0 does not create validator/key-manager/validator-api-bearer and does not start keymanager API when the Engine API is still starting as it starts.

This can keep users of Eth Docker from using the keymanager API. This appears to be a fairly recent issue.

Steps to Reproduce (Bug)

Run a fresh install of Teku 23.9.0 with --data-path=/var/lib/teku and validator API enabled:

      - --validator-api-enabled=true
      - --validator-api-interface=0.0.0.0
      - --validator-api-port=${KEY_API_PORT:-7500}
      - --validator-api-host-allowlist=*
      - --validator-api-cors-origins=*
      - --validator-api-keystore-file=/var/lib/teku/teku-keyapi.keystore
      - --validator-api-keystore-password-file=/var/lib/teku/teku-keyapi.password

Observe whether /var/lib/teku/validator/key-manager/validator-api-bearer is being created and keymanager API starts.

Frequency:

Reproducible.

Falling back to Teku v23.8.0 resolves the issue.

Versions (Add all that apply)

Software version: teku/v23.9.0/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17

Logs

See below for failure and success logs.

yorickdowne commented 1 year ago

Startup logs in full on fresh 23.9.0 with engine API starting as Teku starts

eth-docker-devel-consensus-1  | Checkpoint sync enabled
eth-docker-devel-consensus-1  | MEV Boost enabled
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Setting logging level to INFO
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Configuring logging for destination: console
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes events: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes validator duties: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes color: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Include P2P warnings set to: false
eth-docker-devel-consensus-1  | 2023-09-12 11:57:45.113 INFO  - '--validators-builder-registration-default-enabled' requires '--validators-proposer-blinded-blocks-enabled', enabling it
eth-docker-devel-consensus-1  | 2023-09-12 11:57:45.133 INFO  - During block production, locally produced payload will be chosen when its value is equal or greater than 100% of the builder bid value. Can be configured via --builder-bid-compare-factor
eth-docker-devel-consensus-1  | 2023-09-12 11:57:45.617 INFO  - Teku version: teku/v23.9.0/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17
eth-docker-devel-consensus-1  | 2023-09-12 11:57:45.618 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
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.011 INFO  - Configuration | Network: prater, Storage Mode: MINIMAL
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.012 INFO  - Host Configuration | Maximum Heap Size: 4.00 GB, Total Memory: 31.34 GB, CPU Cores: 8
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.012 INFO  - Rest Api Configuration | Enabled: true, Listen Address: 0.0.0.0, Port: 5052, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.012 INFO  - Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.787 INFO  - JWT secret loaded from /var/lib/teku/ee-secret/jwtsecret
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.809 INFO  - Using execution engine at http://execution:8551
eth-docker-devel-consensus-1  | 2023-09-12 11:57:46.809 INFO  - Enabling Builder Circuit Breaker
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.001 INFO  - Eth1 endpoint not provided, using execution engine endpoint for eth1 data
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.601 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.627 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.713 INFO  - Storing beacon chain data in: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.785 WARN  - Failed to load public keys from external signer.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.792 INFO  - Using portable BLST library.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:47.811 INFO  - Starting metrics http service on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.184 INFO  - Metrics service started and listening on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.189 INFO  - Beacon data directory set to: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.427 INFO  - Created leveldb2 Hot and Finalized database (leveldb2) at /var/lib/teku/beacon/db
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.610 INFO  - Using default implementation for ThreadExecutor
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.687 INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.687 INFO  - Quartz Scheduler v.2.3.2 created.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.688 INFO  - RAMJobStore initialized.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.688 INFO  - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'QuartzScheduler' with instanceId 'NON_CLUSTERED'
eth-docker-devel-consensus-1  |   Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
eth-docker-devel-consensus-1  |   NOT STARTED.
eth-docker-devel-consensus-1  |   Currently in standby mode.
eth-docker-devel-consensus-1  |   Number of jobs executed: 0
eth-docker-devel-consensus-1  |   Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 1 threads.
eth-docker-devel-consensus-1  |   Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.689 INFO  - Quartz scheduler 'QuartzScheduler' initialized from an externally provided properties instance.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.689 INFO  - Quartz scheduler version: 2.3.2
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.720 INFO  - Initializing storage
eth-docker-devel-consensus-1  | 2023-09-12 11:57:48.921 INFO  - Pruning finalized blocks before slot 5444128
eth-docker-devel-consensus-1  | 2023-09-12 11:57:49.007 INFO  - Finalized blocks before slot 5444128 have been pruned.
eth-docker-devel-consensus-1  | 2023-09-12 11:57:57.796 INFO  - Storage initialization complete
eth-docker-devel-consensus-1  | 2023-09-12 11:57:57.797 WARN  - Not loading specified initial state as chain data already exists.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:00.508 INFO  - BLS: loaded BLST library
eth-docker-devel-consensus-1  | 2023-09-12 11:58:08.210 INFO  - Completed regeneration of state for block 0xb658921c65626318e6c9da5a2819787b18898267b60eeb4386ba632bb17c6058 at slot 6500927 by replaying 26 blocks. Took 10364ms
eth-docker-devel-consensus-1  | 2023-09-12 11:58:13.027 INFO  - Execution Client is online
eth-docker-devel-consensus-1  | 2023-09-12 11:58:13.094 INFO  - Loading generated p2p private key from: generated-node-key
eth-docker-devel-consensus-1  | 2023-09-12 11:58:14.628 INFO  - PreGenesis Local ENR: enr:-Iu4QDBYbXtPu9PbP4wPxRXGkJUNrfMEltvb8X9pEf5Titv9H-TlDLcVdr5hRO8mM6o3BxB6o4UfuzY0H1Ynn6wTJH8dhGV0aDKQ5L6TkwAAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 11:58:14.641 INFO  - Using multipeer sync
eth-docker-devel-consensus-1  | 2023-09-12 11:58:14.824 INFO  - Using 8 threads for handling validator API channel
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.613 INFO  - Starting libp2p network...
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.623 INFO  - Listening for connections on: /ip4/172.16.29.5/tcp/9010/p2p/16Uiu2HAmUDT2MU6coUyHeC22nJgfzguCmnir4VthBbeE97tpvr1u
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.632 INFO  - Starting discovery server on UDP port 9010
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.651 INFO  - UDP discovery client started
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.656 INFO  - Begin historical sync of blocks from slot 6500673 to slot 5444127
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.690 INFO  - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.791 INFO  - Local ENR: enr:-Iu4QOzlpOSvUoLYsf7XX01MBcVFIRfDyZKcuYEGcgJdyHejYU8HUlJiQiwOb5OdEEjyzqLtI8p2RLtgwR0Y3Qk9-JcehGV0aDKQYolB7wMAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.795 INFO  - Starting eth2 gossip
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.830 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-12 11:58:16.945 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.018 INFO  - Started i.j.j.@71deab31{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.034 INFO  - Started ServerConnector@1b642ad8{HTTP/1.1, (http/1.1)}{0.0.0.0:5052}
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.087 INFO  - Started Server@161fde19{STARTING}[11.0.15,sto=0] @40768ms
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.088 INFO  - Syncing     *** Target slot: 6500991, Head slot: 6500987, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.122 INFO  - Listening on http://localhost:5052/
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.135 INFO  - Loading deposit tree snapshot from jar:file:/opt/teku/lib/teku-services-powchain-23.9.0.jar!/tech/pegasys/teku/services/powchain/goerli.ssz
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.196 INFO  - A deposit snapshot was read with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.198 INFO  - Loading deposit tree snapshot from database
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.205 INFO  - Loaded deposits tree state from snapshot with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.304 INFO  - Loading deposits up to Eth1 block 0
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.506 INFO  - Epoch Event *** Epoch: 203156, Justified checkpoint: 203154, Finalized checkpoint: 203153, Finalized root: 5477f5028294fe2b3a8587bc9397034d325d5397f6369d37027df631d138e36d
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.747 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 11:58:17.747 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 11:58:18.101 WARN  - The builder is not available: java.util.concurrent.TimeoutException. Block production will fallback to the execution engine.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:18.103 INFO  - The builder is available. It will be used for block production.
eth-docker-devel-consensus-1  | 2023-09-12 11:58:30.644 INFO  - Completed regeneration of state for block 0x62bceeffaf25e6ace1bccd72548dc54962e54d37326fa2e33384b2560d80e8be at slot 6500987 by replaying 52 blocks. Took 17982ms

yorickdowne commented 1 year ago

Upon further testing, this may be an issue with the keymanager API not starting, and maybe unrelated to the data dir location.

Updated Teku to 23.9.0 from 23.8.0, observed that keymanager API started Restarted Teku 23.9.0, and there is no log line for the keymanager API starting on 7500:

eth-docker-devel-consensus-1  | Checkpoint sync enabled
eth-docker-devel-consensus-1  | MEV Boost enabled
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Setting logging level to INFO
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Configuring logging for destination: console
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes events: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes validator duties: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes color: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Include P2P warnings set to: false
eth-docker-devel-consensus-1  | 2023-09-12 12:23:07.438 INFO  - '--validators-builder-registration-default-enabled' requires '--validators-proposer-blinded-blocks-enabled', enabling it
eth-docker-devel-consensus-1  | 2023-09-12 12:23:07.515 INFO  - During block production, locally produced payload will be chosen when its value is equal or greater than 100% of the builder bid value. Can be configured via --builder-bid-compare-factor
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.106 INFO  - Teku version: teku/v23.9.0/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.106 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
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.596 INFO  - Configuration | Network: prater, Storage Mode: MINIMAL
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.597 INFO  - Host Configuration | Maximum Heap Size: 4.00 GB, Total Memory: 31.34 GB, CPU Cores: 8
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.598 INFO  - Rest Api Configuration | Enabled: true, Listen Address: 0.0.0.0, Port: 5052, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 12:23:08.598 INFO  - Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 12:23:09.313 INFO  - JWT secret loaded from /var/lib/teku/ee-secret/jwtsecret
eth-docker-devel-consensus-1  | 2023-09-12 12:23:09.347 INFO  - Using execution engine at http://execution:8551
eth-docker-devel-consensus-1  | 2023-09-12 12:23:09.347 INFO  - Enabling Builder Circuit Breaker
eth-docker-devel-consensus-1  | 2023-09-12 12:23:09.511 INFO  - Eth1 endpoint not provided, using execution engine endpoint for eth1 data
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.024 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.094 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.115 INFO  - Storing beacon chain data in: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.125 WARN  - Failed to load public keys from external signer.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.130 INFO  - Using portable BLST library.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.137 INFO  - Starting metrics http service on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.399 INFO  - Metrics service started and listening on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.403 INFO  - Beacon data directory set to: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.595 INFO  - Created leveldb2 Hot and Finalized database (leveldb2) at /var/lib/teku/beacon/db
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.658 INFO  - Using default implementation for ThreadExecutor
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.697 INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.697 INFO  - Quartz Scheduler v.2.3.2 created.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.699 INFO  - RAMJobStore initialized.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.700 INFO  - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'QuartzScheduler' with instanceId 'NON_CLUSTERED'
eth-docker-devel-consensus-1  |   Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
eth-docker-devel-consensus-1  |   NOT STARTED.
eth-docker-devel-consensus-1  |   Currently in standby mode.
eth-docker-devel-consensus-1  |   Number of jobs executed: 0
eth-docker-devel-consensus-1  |   Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 1 threads.
eth-docker-devel-consensus-1  |   Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.700 INFO  - Quartz scheduler 'QuartzScheduler' initialized from an externally provided properties instance.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.700 INFO  - Quartz scheduler version: 2.3.2
eth-docker-devel-consensus-1  | 2023-09-12 12:23:10.737 INFO  - Initializing storage
eth-docker-devel-consensus-1  | 2023-09-12 12:23:11.100 INFO  - Pruning finalized blocks before slot 5444256
eth-docker-devel-consensus-1  | 2023-09-12 12:23:11.217 INFO  - Finalized blocks before slot 5444256 have been pruned.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:20.680 INFO  - Storage initialization complete
eth-docker-devel-consensus-1  | 2023-09-12 12:23:20.681 WARN  - Not loading specified initial state as chain data already exists.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:23.112 INFO  - BLS: loaded BLST library
eth-docker-devel-consensus-1  | 2023-09-12 12:23:32.324 INFO  - Completed regeneration of state for block 0xc1594631c52fa89d52577589b8f2d606cd6ac6bf560ac7c800659db2df5650d9 at slot 6501056 by replaying 27 blocks. Took 11592ms
eth-docker-devel-consensus-1  | 2023-09-12 12:23:32.804 ERROR - Execution Client request failed. Make sure the Execution Client is online and can respond to requests.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:32.811 ERROR - Failed to update fork choice
eth-docker-devel-consensus-1  | java.util.concurrent.CompletionException: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.complete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.complete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenCompleteStage(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.whenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:626) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:33) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.propagateResult(SafeFuture.java:143) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$exceptionallyCompose$34(SafeFuture.java:426) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:146) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at org.web3j.utils.Async.lambda$run$1(Async.java:40) ~[core-4.10.1.jar:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$AsyncRun.run(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | at java.lang.Thread.run(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | Caused by: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | at tech.pegasys.teku.ethereum.executionclient.response.ResponseUnwrapper.unwrapResponseOrThrow(ResponseUnwrapper.java:34) ~[teku-ethereum-executionclient-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.ethereum.executionclient.response.ResponseUnwrapper.unwrapExecutionClientResponseOrThrow(ResponseUnwrapper.java:21) ~[teku-ethereum-executionclient-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | ... 30 more
eth-docker-devel-consensus-1  | 2023-09-12 12:23:33.000 INFO  - Loading generated p2p private key from: generated-node-key
eth-docker-devel-consensus-1  | 2023-09-12 12:23:34.119 INFO  - PreGenesis Local ENR: enr:-Iu4QCQQEWcuObpt89ywem54fEk09s_UbSxQC5TbZrENZnyzbBP2Dt-ZGJ-y7dqdF6nMTOzUF7uN-UNjUhfptI7KZ0QrhGV0aDKQ5L6TkwAAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 12:23:34.132 INFO  - Using multipeer sync
eth-docker-devel-consensus-1  | 2023-09-12 12:23:34.293 INFO  - Using 8 threads for handling validator API channel
eth-docker-devel-consensus-1  | 2023-09-12 12:23:35.949 ERROR - Exception exchanging Engine API capabilities
eth-docker-devel-consensus-1  | java.util.concurrent.CompletionException: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.encodeThrowable(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeThrowable(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniApply.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.complete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:146) ~[teku-infrastructure-async-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.uniWhenComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.postComplete(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source) ~[?:?]
eth-docker-devel-consensus-1  | at org.web3j.utils.Async.lambda$run$1(Async.java:40) ~[core-4.10.1.jar:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.CompletableFuture$AsyncRun.run(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | at java.lang.Thread.run(Unknown Source) [?:?]
eth-docker-devel-consensus-1  | Caused by: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | at tech.pegasys.teku.ethereum.executionclient.response.ResponseUnwrapper.unwrapResponseOrThrow(ResponseUnwrapper.java:34) ~[teku-ethereum-executionclient-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | at tech.pegasys.teku.ethereum.executionclient.response.ResponseUnwrapper.unwrapExecutionClientResponseOrThrow(ResponseUnwrapper.java:21) ~[teku-ethereum-executionclient-23.9.0.jar:23.9.0]
eth-docker-devel-consensus-1  | ... 18 more
eth-docker-devel-consensus-1  | 2023-09-12 12:23:35.985 INFO  - Starting libp2p network...
eth-docker-devel-consensus-1  | 2023-09-12 12:23:35.994 INFO  - Listening for connections on: /ip4/172.16.30.13/tcp/9010/p2p/16Uiu2HAmUDT2MU6coUyHeC22nJgfzguCmnir4VthBbeE97tpvr1u
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.000 INFO  - Starting discovery server on UDP port 9010
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.018 INFO  - UDP discovery client started
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.022 INFO  - Begin historical sync of blocks from slot 6500673 to slot 5444255
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.022 INFO  - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.099 INFO  - Syncing     *** Target slot: 6501117, Head slot: 6501113, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.187 INFO  - Local ENR: enr:-Iu4QAU2YOy2BPchN9Wvp1c0qrMxy5C5Wx4sP0QNiQiuKaILT_CbAX6TDwXcLcdQwMllU7gDJssbW-v8TuzjzbXtzscshGV0aDKQYolB7wMAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.198 INFO  - Starting eth2 gossip
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.289 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.429 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.497 INFO  - Started i.j.j.@70fec42b{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.508 INFO  - Started ServerConnector@442f0f03{HTTP/1.1, (http/1.1)}{0.0.0.0:5052}
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.511 INFO  - Started Server@79fd1b56{STARTING}[11.0.15,sto=0] @37916ms
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.517 INFO  - Syncing     *** Target slot: 6501118, Head slot: 6501113, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.620 INFO  - Listening on http://localhost:5052/
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.633 INFO  - Loading deposit tree snapshot from jar:file:/opt/teku/lib/teku-services-powchain-23.9.0.jar!/tech/pegasys/teku/services/powchain/goerli.ssz
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.691 INFO  - A deposit snapshot was read with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.697 INFO  - Loading deposit tree snapshot from database
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.710 INFO  - Loaded deposits tree state from snapshot with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.725 WARN  - Endpoint http://execution:8551 encountered an issue | Connection refused
eth-docker-devel-consensus-1  | 2023-09-12 12:23:36.940 WARN  - The builder is not available: java.util.concurrent.TimeoutException. Block production will fallback to the execution engine.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:37.058 INFO  - The builder is available. It will be used for block production.
eth-docker-devel-consensus-1  | 2023-09-12 12:23:40.487 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:23:40.488 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:23:45.630 INFO  - Completed regeneration of state for block 0x8e4da74a8f2dc5df6a858ca0405d642a9cd23e25720d6b287ff2d89364698011 at slot 6501113 by replaying 46 blocks. Took 12972ms
eth-docker-devel-consensus-1  | 2023-09-12 12:23:48.005 INFO  - Syncing     *** Target slot: 6501119, Head slot: 6501113, Waiting for execution layer sync, Connected peers: 5
eth-docker-devel-consensus-1  | 2023-09-12 12:23:52.517 ERROR - Unable to import block: Execution Client returned an error: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | 2023-09-12 12:23:54.518 INFO  - Retrying execution of block 8ac8d1317ceaa80c2ff82c5c5f1ea4689d7826b5d84f6d049e8b3f05ac1560e3 (6501114)
eth-docker-devel-consensus-1  | 2023-09-12 12:23:54.639 ERROR - Unable to import block: Execution Client returned an error: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | 2023-09-12 12:23:58.640 INFO  - Retrying execution of block 8ac8d1317ceaa80c2ff82c5c5f1ea4689d7826b5d84f6d049e8b3f05ac1560e3 (6501114)
eth-docker-devel-consensus-1  | 2023-09-12 12:23:59.505 ERROR - Unable to import block: Execution Client returned an error: tech.pegasys.teku.ethereum.executionclient.response.InvalidRemoteResponseException: Invalid remote response from the execution client: Failed to connect to execution/172.16.30.11:8551
eth-docker-devel-consensus-1  | 2023-09-12 12:24:00.022 INFO  - Syncing     *** Target slot: 6501120, Head slot: 6501113, Waiting for execution layer sync, Connected peers: 9
eth-docker-devel-consensus-1  | 2023-09-12 12:24:02.137 INFO  - Loading deposits up to Eth1 block 0
eth-docker-devel-consensus-1  | 2023-09-12 12:24:07.506 INFO  - Retrying execution of block 8ac8d1317ceaa80c2ff82c5c5f1ea4689d7826b5d84f6d049e8b3f05ac1560e3 (6501114)
eth-docker-devel-consensus-1  | 2023-09-12 12:24:07.587 INFO  - Execution Client is responding to requests again after a previous failure
eth-docker-devel-consensus-1  | 2023-09-12 12:24:23.918 INFO  - Completed regeneration of state for block 0xdf6a5acc113f85b5a7fdac14fc226710830171bf89a80d0b7fd4b9107bfaffba at slot 6501086 by replaying 24 blocks. Took 11914ms

Restarted Teku again but left execution client running, now keymanager API starts. One sec, more tests.

yorickdowne commented 1 year ago

Success logs when Engine API is already up as Teku 23.9.0 starts.

eth-docker-devel-consensus-1  | Checkpoint sync enabled
eth-docker-devel-consensus-1  | MEV Boost enabled
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Setting logging level to INFO
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Configuring logging for destination: console
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes events: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes validator duties: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes color: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Include P2P warnings set to: false
eth-docker-devel-consensus-1  | 2023-09-12 12:28:46.919 INFO  - '--validators-builder-registration-default-enabled' requires '--validators-proposer-blinded-blocks-enabled', enabling it
eth-docker-devel-consensus-1  | 2023-09-12 12:28:46.938 INFO  - During block production, locally produced payload will be chosen when its value is equal or greater than 100% of the builder bid value. Can be configured via --builder-bid-compare-factor
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.325 INFO  - Teku version: teku/v23.9.0/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.325 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
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.567 INFO  - Configuration | Network: prater, Storage Mode: MINIMAL
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.567 INFO  - Host Configuration | Maximum Heap Size: 4.00 GB, Total Memory: 31.34 GB, CPU Cores: 8
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.567 INFO  - Rest Api Configuration | Enabled: true, Listen Address: 0.0.0.0, Port: 5052, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.567 INFO  - Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.832 INFO  - JWT secret loaded from /var/lib/teku/ee-secret/jwtsecret
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.853 INFO  - Using execution engine at http://execution:8551
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.853 INFO  - Enabling Builder Circuit Breaker
eth-docker-devel-consensus-1  | 2023-09-12 12:28:47.963 INFO  - Eth1 endpoint not provided, using execution engine endpoint for eth1 data
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.210 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.225 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.247 INFO  - Storing beacon chain data in: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.285 INFO  - Using portable BLST library.
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.297 INFO  - Starting metrics http service on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.324 INFO  - BLS: loaded BLST library
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.328 INFO  - Loading 2 validator keys...
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.340 INFO  - Loaded 2 Validators: 9642bbe, 8fe5b2c
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.511 INFO  - Metrics service started and listening on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.516 INFO  - Beacon data directory set to: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.681 INFO  - Created leveldb2 Hot and Finalized database (leveldb2) at /var/lib/teku/beacon/db
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.800 INFO  - Using default implementation for ThreadExecutor
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.816 INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.816 INFO  - Quartz Scheduler v.2.3.2 created.
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.817 INFO  - RAMJobStore initialized.
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.818 INFO  - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'QuartzScheduler' with instanceId 'NON_CLUSTERED'
eth-docker-devel-consensus-1  |   Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
eth-docker-devel-consensus-1  |   NOT STARTED.
eth-docker-devel-consensus-1  |   Currently in standby mode.
eth-docker-devel-consensus-1  |   Number of jobs executed: 0
eth-docker-devel-consensus-1  |   Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 1 threads.
eth-docker-devel-consensus-1  |   Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.819 INFO  - Quartz scheduler 'QuartzScheduler' initialized from an externally provided properties instance.
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.819 INFO  - Quartz scheduler version: 2.3.2
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.842 INFO  - Initializing storage
eth-docker-devel-consensus-1  | 2023-09-12 12:28:48.954 INFO  - Pruning finalized blocks before slot 5444288
eth-docker-devel-consensus-1  | 2023-09-12 12:28:49.009 INFO  - Finalized blocks before slot 5444288 have been pruned.
eth-docker-devel-consensus-1  | 2023-09-12 12:28:56.879 INFO  - Storage initialization complete
eth-docker-devel-consensus-1  | 2023-09-12 12:28:56.879 WARN  - Not loading specified initial state as chain data already exists.
eth-docker-devel-consensus-1  | 2023-09-12 12:29:05.361 INFO  - Completed regeneration of state for block 0xdf6a5acc113f85b5a7fdac14fc226710830171bf89a80d0b7fd4b9107bfaffba at slot 6501086 by replaying 24 blocks. Took 8431ms
eth-docker-devel-consensus-1  | 2023-09-12 12:29:09.122 INFO  - Execution Client is online
eth-docker-devel-consensus-1  | 2023-09-12 12:29:09.241 INFO  - Loading generated p2p private key from: generated-node-key
eth-docker-devel-consensus-1  | 2023-09-12 12:29:10.244 INFO  - PreGenesis Local ENR: enr:-Iu4QFTxlEC1c5OdOJhcIfKrfRr69RTlriEf6EJV-2IH97Fpa_e0ffBCs03Zy9ft-VB4S8kjUEyXglDz6jN6fxcRwIE1hGV0aDKQ5L6TkwAAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 12:29:10.256 INFO  - Using multipeer sync
eth-docker-devel-consensus-1  | 2023-09-12 12:29:10.402 INFO  - Using 8 threads for handling validator API channel
eth-docker-devel-consensus-1  | 2023-09-12 12:29:10.910 INFO  - Starting libp2p network...
eth-docker-devel-consensus-1  | 2023-09-12 12:29:10.920 INFO  - Listening for connections on: /ip4/172.16.30.13/tcp/9010/p2p/16Uiu2HAmUDT2MU6coUyHeC22nJgfzguCmnir4VthBbeE97tpvr1u
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.097 INFO  - Starting discovery server on UDP port 9010
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.131 INFO  - UDP discovery client started
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.133 INFO  - Begin historical sync of blocks from slot 6500673 to slot 5444287
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.141 INFO  - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.228 INFO  - Syncing     *** Target slot: 6501145, Head slot: 6501143, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.299 INFO  - Local ENR: enr:-Iu4QCI3e91Dvqb_rYFIkSW4bYfLhRWeI6j78-UepF57JiLeAt9vX0z6J57UKcZA5qs1LMC6tRS4j50YgrTpLTD8YCM2hGV0aDKQYolB7wMAECD__________4JpZIJ2NIlzZWNwMjU2azGhA-cwDLQuG5S3f5V9kozQoIIfdYKs1vz8xADtULmFTAOw
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.303 INFO  - Starting eth2 gossip
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.321 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.521 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.692 INFO  - Started i.j.j.@1206bdba{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.718 INFO  - Started ServerConnector@546bd19e{HTTP/1.1, (http/1.1)}{0.0.0.0:5052}
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.727 INFO  - Started Server@1edeeddd{STARTING}[11.0.15,sto=0] @27825ms
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.788 INFO  - Listening on http://localhost:5052/
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.808 INFO  - Loading deposit tree snapshot from jar:file:/opt/teku/lib/teku-services-powchain-23.9.0.jar!/tech/pegasys/teku/services/powchain/goerli.ssz
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.823 INFO  - A deposit snapshot was read with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.825 INFO  - Loading deposit tree snapshot from database
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.839 INFO  - Loaded deposits tree state from snapshot with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.840 INFO  - Initializing API auth access file /var/lib/teku/validator/key-manager/validator-api-bearer
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.888 INFO  - Loading deposits up to Eth1 block 0
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.888 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.904 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.906 INFO  - Started i.j.j.@373f5b69{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.998 INFO  - x509=X509@55e109e9(teku-keyapi,h=[localhost, consensus, validator, teku-keyapi-cert],a=[/127.0.0.1],w=[]) for Server@48fd242a[provider=Conscrypt,keyStore=file:///var/lib/teku/teku-keyapi.keystore,trustStore=null]
eth-docker-devel-consensus-1  | 2023-09-12 12:29:11.999 INFO  - Unable to get KeyManagerFactory instance for algorithm [SunX509] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.005 INFO  - Syncing     *** Target slot: 6501146, Head slot: 6501143, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.013 INFO  - Unable to get TrustManagerFactory instance for algorithm [PKIX] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.014 INFO  - Unable to get SSLContext instance for protocol [TLS] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.023 INFO  - Started ServerConnector@18b3b383{SSL, (ssl, http/1.1)}{0.0.0.0:7500}
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.024 INFO  - Started Server@55692aa{STARTING}[11.0.15,sto=0] @28122ms
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.025 INFO  - Listening on http://localhost:7500/

mehdi-aouadi commented 1 year ago

Hi Yorick, I'm unable to reproduce the bearer non created issue. I started a fresh 23.9.0 Teku with the validator API enabled and with a dummy EL url and it created it (Log: Initializing API auth access file..., when it already exists, after a Teku restart, there is no such log which is normal). Regarding the key manager API startup, I see the log: Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*] in all the log snippets which means that the API has started correctly. Are we talking about the same success/failure logs?

Are these these logs before or after you restarted or both (I don't see a restart)? Are you deleting the bearer, if any, and the data dir before each test?

yorickdowne commented 1 year ago

Regarding the key manager API startup, I see the log: Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*] in all the log snippets which means that the API has started correctly.

Does not actually, it has started up successfully when I see

eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.023 INFO  - Started ServerConnector@18b3b383{SSL, (ssl, http/1.1)}{0.0.0.0:7500}
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.024 INFO  - Started Server@55692aa{STARTING}[11.0.15,sto=0] @28122ms
eth-docker-devel-consensus-1  | 2023-09-12 12:29:12.025 INFO  - Listening on http://localhost:7500/

So what I see in failure case is:

Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
No Listening on http://localhost:7500/
bearer token missing if it didn't exist
If bearer token already existed, in failure case API calls will fail because it never started Listening

rolfyone commented 1 year ago

The interesting thing here for me is that it's not happening in 23.8, because I'm not sure we've really changed anything, but will try to replicate so that i can take a closer look.

rolfyone commented 1 year ago

From what I can see, if we're not seeing 'listening on XXX', then the rest api has silently failed to startup, with no real reason why, because only BindExceptions were looked at, the rest got swallowed.

There's a couple of InvalidStateExceptions which are pretty terminal, which then just silently disappear, which is sub-optimal. Im tempted to push them up, and fail the instance startup because its something important that the user asked for, like the bearer-auth file not being able to be written (which is how i replicated the 'not seeing listening on').

rolfyone commented 1 year ago

I only put that PR as 'partially addresses' because it would only identify what happened, not stop whatever went boom @yorickdowne

yorickdowne commented 1 year ago

Awesome let me try the PR and see whether it highlights cause! Since I seem to be able to replicate this.

yorickdowne commented 1 year ago

Amazing, I cannot reproduce any more. Brilliant. Hang loose please.

It'd be hilarious if this was a frankenbug. Will let it sync fully, try to reproduce on the PR, then if I can't, try without the PR. We shall see.

yorickdowne commented 1 year ago

I think I have this reproduced, and it may be related to an interplay with web3signer. Not entirely sure yet, but I can reproduce when I am using web3signer.

I don't see anything enlightening in logs though re what's happening. I am running on PR 7506.

eth-docker-devel-consensus-1  | INFO StatusConsoleListener Setting logging level to INFO
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Configuring logging for destination: console
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes events: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes validator duties: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes color: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Include P2P warnings set to: false
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.326 INFO  - Teku version: teku/v23.9.0+25-g4c7c656b5/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.330 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
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.687 INFO  - Configuration | Network: prater, Storage Mode: MINIMAL
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.688 INFO  - Host Configuration | Maximum Heap Size: 4.00 GB, Total Memory: 31.34 GB, CPU Cores: 8
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.688 INFO  - Rest Api Configuration | Enabled: true, Listen Address: 0.0.0.0, Port: 5052, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-18 17:57:50.688 INFO  - Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-18 17:57:51.201 INFO  - JWT secret loaded from /var/lib/teku/ee-secret/jwtsecret
eth-docker-devel-consensus-1  | 2023-09-18 17:57:51.295 INFO  - Using execution engine at http://execution:8551
eth-docker-devel-consensus-1  | 2023-09-18 17:57:51.295 INFO  - Enabling Builder Circuit Breaker
eth-docker-devel-consensus-1  | 2023-09-18 17:57:51.623 INFO  - Eth1 endpoint not provided, using execution engine endpoint for eth1 data
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.116 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.133 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.197 INFO  - Storing beacon chain data in: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.200 WARN  - Failed to load public keys from external signer.
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.206 INFO  - Starting metrics http service on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.427 INFO  - Metrics service started and listening on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.430 INFO  - Beacon data directory set to: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.625 INFO  - Created leveldb2 Hot and Finalized database (leveldb2) at /var/lib/teku/beacon/db
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.736 INFO  - Using default implementation for ThreadExecutor
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.794 INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.794 INFO  - Quartz Scheduler v.2.3.2 created.
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.795 INFO  - RAMJobStore initialized.
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.796 INFO  - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'QuartzScheduler' with instanceId 'NON_CLUSTERED'
eth-docker-devel-consensus-1  |   Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
eth-docker-devel-consensus-1  |   NOT STARTED.
eth-docker-devel-consensus-1  |   Currently in standby mode.
eth-docker-devel-consensus-1  |   Number of jobs executed: 0
eth-docker-devel-consensus-1  |   Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 1 threads.
eth-docker-devel-consensus-1  |   Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.796 INFO  - Quartz scheduler 'QuartzScheduler' initialized from an externally provided properties instance.
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.796 INFO  - Quartz scheduler version: 2.3.2
eth-docker-devel-consensus-1  | 2023-09-18 17:57:52.833 INFO  - Initializing storage
eth-docker-devel-consensus-1  | 2023-09-18 17:57:53.135 INFO  - Initiating pruning of finalized blocks prior to slot 5489120.
eth-docker-devel-consensus-1  | 2023-09-18 17:57:53.324 INFO  - Pruned 5000 finalized blocks prior to slot 5489120, last pruned slot was 5489119.
eth-docker-devel-consensus-1  | 2023-09-18 17:58:04.285 INFO  - Storage initialization complete
eth-docker-devel-consensus-1  | 2023-09-18 17:58:04.286 WARN  - Not loading specified initial state as chain data already exists.
eth-docker-devel-consensus-1  | 2023-09-18 17:58:07.232 INFO  - BLS: loaded BLST library
eth-docker-devel-consensus-1  | 2023-09-18 17:58:17.417 INFO  - Completed regeneration of state for block 0x621f94ebb23749d6a122f8243362340395e4f1842d78cc1dd516731349504f8f at slot 6545920 by replaying 24 blocks. Took 13077ms
eth-docker-devel-consensus-1  | 2023-09-18 17:58:18.914 INFO  - Loading generated p2p private key from: generated-node-key
eth-docker-devel-consensus-1  | 2023-09-18 17:58:19.627 INFO  - Execution Client is online
eth-docker-devel-consensus-1  | 2023-09-18 17:58:20.509 INFO  - PreGenesis Local ENR: enr:-Iu4QHn1JZ7GL0IdwkuPt0hKluX9FK0PkEbpwTCV0XQa9YelHqBPY9CHCgkKksL6UMSpl37DmN2QQMp3Ka9iD5az3bcqhGV0aDKQ5L6TkwAAECD__________4JpZIJ2NIlzZWNwMjU2azGhAv4orR9dPrJT5AL7yF5LPH0UJzmZ9e8NtRHsr3pMvl16
eth-docker-devel-consensus-1  | 2023-09-18 17:58:20.519 INFO  - Using multipeer sync
eth-docker-devel-consensus-1  | 2023-09-18 17:58:20.825 INFO  - Using 8 threads for handling validator API channel
eth-docker-devel-consensus-1  | 2023-09-18 17:58:22.429 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 17:58:22.431 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.002 INFO  - Starting libp2p network...
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.111 INFO  - Starting discovery server on UDP port 9010
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.113 INFO  - Listening for connections on: /ip4/172.16.13.4/tcp/9010/p2p/16Uiu2HAmCXoWWHhDmaGJv3RLpQdXY5kEezQF3fDgTU5hnoNESgrD
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.210 INFO  - UDP discovery client started
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.300 INFO  - Begin historical sync of blocks from slot 6545697 to slot 5489119
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.313 INFO  - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.498 INFO  - Syncing     *** Target slot: 6545991, Head slot: 6545970, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.509 INFO  - Syncing     *** Target slot: 6545992, Head slot: 6545970, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.603 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.716 INFO  - Local ENR: enr:-Iu4QL4qta-cIEoikYHyQYjNBNHYWnD2Eb1M0XpfS78PUBwVESQ-OZ5U1yYps-fZFZUHe5jUVq1AwN5liejOiCzn6NMrhGV0aDKQYolB7wMAECD__________4JpZIJ2NIlzZWNwMjU2azGhAv4orR9dPrJT5AL7yF5LPH0UJzmZ9e8NtRHsr3pMvl16
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.787 INFO  - Starting eth2 gossip
eth-docker-devel-consensus-1  | 2023-09-18 17:58:24.923 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.018 INFO  - Started i.j.j.@2601ff6a{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.036 INFO  - Started ServerConnector@3d01d757{HTTP/1.1, (http/1.1)}{0.0.0.0:5052}
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.038 INFO  - Started Server@152af0eb{STARTING}[11.0.15,sto=0] @40600ms
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.110 INFO  - Listening on http://localhost:5052/
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.130 INFO  - Loading deposit tree snapshot from jar:file:/opt/teku/lib/teku-services-powchain-develop.jar!/tech/pegasys/teku/services/powchain/goerli.ssz
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.231 INFO  - A deposit snapshot was read with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.232 INFO  - Loading deposit tree snapshot from database
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.293 INFO  - Loaded deposits tree state from snapshot with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-18 17:58:25.906 INFO  - Loading deposits up to Eth1 block 0
eth-docker-devel-consensus-1  | 2023-09-18 17:58:36.015 INFO  - Syncing     *** Target slot: 6545993, Head slot: 6545970, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-18 17:58:38.912 INFO  - Completed regeneration of state for block 0x09c79721acd952efc7e1abad6a252da315a5ff01652a5f3a809093fc0869252e at slot 6545970 by replaying 38 blocks. Took 20905ms
eth-docker-devel-consensus-1  | 2023-09-18 17:58:48.012 INFO  - Syncing     *** Target slot: 6545994, Head slot: 6545970, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-18 17:59:02.023 INFO  - Syncing     *** Target slot: 6545995, Head slot: 6545975, Waiting for execution layer sync, Connected peers: 8
eth-docker-devel-consensus-1  | 2023-09-18 17:59:35.201 INFO  - Completed regeneration of state for block 0xb047b0011b4662257d47b3dc5a56594bda841dae1c4c127b2f8d469502bb1bac at slot 6545952 by replaying 25 blocks. Took 23198ms
eth-docker-devel-consensus-1  | 2023-09-18 17:59:37.723 INFO  - Syncing     *** Target slot: 6545996, Head slot: 6545991, Waiting for execution layer sync, Connected peers: 9
eth-docker-devel-consensus-1  | 2023-09-18 17:59:40.295 INFO  - Syncing     *** Target slot: 6545997, Head slot: 6545993, Waiting for execution layer sync, Connected peers: 9
eth-docker-devel-consensus-1  | 2023-09-18 17:59:40.703 INFO  - Syncing     *** Target slot: 6545998, Head slot: 6545993, Waiting for execution layer sync, Connected peers: 9
eth-docker-devel-consensus-1  | 2023-09-18 17:59:48.286 INFO  - Syncing     *** Target slot: 6545999, Head slot: 6545995, Waiting for execution layer sync, Connected peers: 8
eth-docker-devel-consensus-1  | 2023-09-18 18:00:00.121 INFO  - Syncing     *** Target slot: 6546000, Head slot: 6545999, Waiting for execution layer sync, Connected peers: 13
eth-docker-devel-consensus-1  | 2023-09-18 18:00:12.119 INFO  - Syncing     *** Target slot: 6546001, Head slot: 6546000, Waiting for execution layer sync, Connected peers: 14
eth-docker-devel-consensus-1  | 2023-09-18 18:00:24.116 INFO  - Syncing     *** Target slot: 6546002, Head slot: 6546001

yorickdowne commented 1 year ago

So maybe it's related to web3signer coming online late. In this log snippet web3signer comes up but no keys are loaded, and keymanager API port never activates

eth-docker-devel-consensus-1  | 2023-09-18 18:05:05.617 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:05:06.019 ERROR - External signer is currently not reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:05:12.004 INFO  - Syncing     *** Target slot: 6546026, Head slot: 6546009, Waiting for execution layer sync, Connected peers: 10
eth-docker-devel-consensus-1  | 2023-09-18 18:05:14.098 INFO  - Completed regeneration of state for block 0xc6e3c2b1f8f4e1a929bd3845a844f5a88270eed6af781655e0cbba4ed68f57be at slot 6546015 by replaying 49 blocks. Took 32668ms
eth-docker-devel-consensus-1  | 2023-09-18 18:05:23.719 INFO  - Reorg Event *** New Head: dfd448dc6d99d4a9c04924487222d79933783b33183187f8ad79ef06de7eed2c (6546016), Previous Head: e6fb1d4b3701f7bb5e868b3ca130ee0013be206851b4c6c59f7b234717b4eb0c (6546009), Common Ancestor: 3df11791c7fe34c12ccb0110d033d903f9f9bb27979ff5d9d149e9f6bda7bd5c (6546007)
eth-docker-devel-consensus-1  | 2023-09-18 18:05:36.399 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:05:36.419 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:05:58.685 INFO  - Completed regeneration of state for block 0xfb3c9314c3af82850f8e8f5bced4dec797d75f31a9df1b2dc2d0b65ddfe55fd8 at slot 6545984 by replaying 24 blocks. Took 34681ms
eth-docker-devel-consensus-1  | 2023-09-18 18:05:59.722 INFO  - Syncing     *** Target slot: 6546027, Head slot: 6546027, Waiting for execution layer sync, Connected peers: 16
eth-docker-devel-consensus-1  | 2023-09-18 18:06:00.429 INFO  - Syncing     *** Target slot: 6546028, Head slot: 6546027, Waiting for execution layer sync, Connected peers: 14
eth-docker-devel-consensus-1  | 2023-09-18 18:06:00.896 INFO  - Syncing     *** Target slot: 6546029, Head slot: 6546027, Waiting for execution layer sync, Connected peers: 15
eth-docker-devel-consensus-1  | 2023-09-18 18:06:01.415 INFO  - Syncing     *** Target slot: 6546030, Head slot: 6546027, Waiting for execution layer sync, Connected peers: 15

yorickdowne commented 1 year ago

Which tbh makes a ton more sense than "engine API". Here it is when web3signer is already up as Teku starts.

eth-docker-devel-consensus-1  | INFO StatusConsoleListener Setting logging level to INFO
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Configuring logging for destination: console
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes events: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes validator duties: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Logging includes color: true
eth-docker-devel-consensus-1  | INFO StatusConsoleListener Include P2P warnings set to: false
eth-docker-devel-consensus-1  | 2023-09-18 18:07:27.996 INFO  - Teku version: teku/v23.9.0+25-g4c7c656b5/linux-x86_64/-eclipseadoptium-openjdk64bitservervm-java-17
eth-docker-devel-consensus-1  | 2023-09-18 18:07:28.002 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
eth-docker-devel-consensus-1  | 2023-09-18 18:07:28.428 INFO  - Configuration | Network: prater, Storage Mode: MINIMAL
eth-docker-devel-consensus-1  | 2023-09-18 18:07:28.428 INFO  - Host Configuration | Maximum Heap Size: 4.00 GB, Total Memory: 31.34 GB, CPU Cores: 8
eth-docker-devel-consensus-1  | 2023-09-18 18:07:28.429 INFO  - Rest Api Configuration | Enabled: true, Listen Address: 0.0.0.0, Port: 5052, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-18 18:07:28.429 INFO  - Validator Api Configuration | Listen Address: 0.0.0.0, Port 7500, Allow: [*]
eth-docker-devel-consensus-1  | 2023-09-18 18:07:29.013 INFO  - JWT secret loaded from /var/lib/teku/ee-secret/jwtsecret
eth-docker-devel-consensus-1  | 2023-09-18 18:07:29.016 INFO  - Using execution engine at http://execution:8551
eth-docker-devel-consensus-1  | 2023-09-18 18:07:29.017 INFO  - Enabling Builder Circuit Breaker
eth-docker-devel-consensus-1  | 2023-09-18 18:07:29.403 INFO  - Eth1 endpoint not provided, using execution engine endpoint for eth1 data
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.031 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.099 INFO  - External signer is reachable at http://web3signer:9000
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.129 INFO  - Storing beacon chain data in: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.206 INFO  - Starting metrics http service on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.400 INFO  - Loading 2 validator keys...
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.490 INFO  - Loaded 2 Validators: 9642bbe, 8fe5b2c
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.622 INFO  - Metrics service started and listening on 0.0.0.0:8008
eth-docker-devel-consensus-1  | 2023-09-18 18:07:30.627 INFO  - Beacon data directory set to: /var/lib/teku/beacon
eth-docker-devel-consensus-1  | 2023-09-18 18:07:31.609 INFO  - Created leveldb2 Hot and Finalized database (leveldb2) at /var/lib/teku/beacon/db
eth-docker-devel-consensus-1  | 2023-09-18 18:07:31.829 INFO  - Using default implementation for ThreadExecutor
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.001 INFO  - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.001 INFO  - Quartz Scheduler v.2.3.2 created.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.002 INFO  - RAMJobStore initialized.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.003 INFO  - Scheduler meta-data: Quartz Scheduler (v2.3.2) 'QuartzScheduler' with instanceId 'NON_CLUSTERED'
eth-docker-devel-consensus-1  |   Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
eth-docker-devel-consensus-1  |   NOT STARTED.
eth-docker-devel-consensus-1  |   Currently in standby mode.
eth-docker-devel-consensus-1  |   Number of jobs executed: 0
eth-docker-devel-consensus-1  |   Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 1 threads.
eth-docker-devel-consensus-1  |   Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.003 INFO  - Quartz scheduler 'QuartzScheduler' initialized from an externally provided properties instance.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.003 INFO  - Quartz scheduler version: 2.3.2
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.033 INFO  - Initializing storage
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.294 INFO  - Initiating pruning of finalized blocks prior to slot 5489184.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:32.425 INFO  - Pruned 5000 finalized blocks prior to slot 5489184, last pruned slot was 5489183.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:47.992 INFO  - Storage initialization complete
eth-docker-devel-consensus-1  | 2023-09-18 18:07:47.993 WARN  - Not loading specified initial state as chain data already exists.
eth-docker-devel-consensus-1  | 2023-09-18 18:07:53.588 INFO  - BLS: loaded BLST library
eth-docker-devel-consensus-1  | 2023-09-18 18:08:11.485 INFO  - Completed regeneration of state for block 0xfb3c9314c3af82850f8e8f5bced4dec797d75f31a9df1b2dc2d0b65ddfe55fd8 at slot 6545984 by replaying 24 blocks. Took 23260ms
eth-docker-devel-consensus-1  | 2023-09-18 18:08:13.094 INFO  - Loading generated p2p private key from: generated-node-key
eth-docker-devel-consensus-1  | 2023-09-18 18:08:13.223 INFO  - Execution Client is online
eth-docker-devel-consensus-1  | 2023-09-18 18:08:15.886 INFO  - PreGenesis Local ENR: enr:-Iu4QMgMNip4kNHIsxbZVe_9-VCTUkl5pFS85XjkUEG4mlgxEMa7-Mf-2njpnIQpcP4gx65L5d6BJ8mxofNJerSpbrI0hGV0aDKQ5L6TkwAAECD__________4JpZIJ2NIlzZWNwMjU2azGhAv4orR9dPrJT5AL7yF5LPH0UJzmZ9e8NtRHsr3pMvl16
eth-docker-devel-consensus-1  | 2023-09-18 18:08:15.895 INFO  - Using multipeer sync
eth-docker-devel-consensus-1  | 2023-09-18 18:08:16.293 INFO  - Using 8 threads for handling validator API channel
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.025 INFO  - Starting libp2p network...
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.111 INFO  - Listening for connections on: /ip4/172.16.13.4/tcp/9010/p2p/16Uiu2HAmCXoWWHhDmaGJv3RLpQdXY5kEezQF3fDgTU5hnoNESgrD
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.118 INFO  - Starting discovery server on UDP port 9010
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.195 INFO  - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.206 INFO  - Begin historical sync of blocks from slot 6545697 to slot 5489183
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.213 INFO  - UDP discovery client started
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.328 INFO  - Syncing     *** Target slot: 6546041, Head slot: 6546030, Waiting for execution layer sync, Connected peers: 0
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.433 INFO  - Local ENR: enr:-Iu4QFo4fXMo7yf-4Cc3MRVVz_-wQYM7feJIYcfl3OXqP8-jAToKitKM29t3-Q_AjhCQSnEax9IpP4lNL0MTmzsRrJY1hGV0aDKQYolB7wMAECD__________4JpZIJ2NIlzZWNwMjU2azGhAv4orR9dPrJT5AL7yF5LPH0UJzmZ9e8NtRHsr3pMvl16
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.486 INFO  - Starting eth2 gossip
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.526 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.739 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.795 INFO  - Started i.j.j.@15b3280{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.804 INFO  - Started ServerConnector@728ac9ee{HTTP/1.1, (http/1.1)}{0.0.0.0:5052}
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.807 INFO  - Started Server@61621b0b{STARTING}[11.0.15,sto=0] @60676ms
eth-docker-devel-consensus-1  | 2023-09-18 18:08:18.998 INFO  - Listening on http://localhost:5052/
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.016 INFO  - Loading deposit tree snapshot from jar:file:/opt/teku/lib/teku-services-powchain-develop.jar!/tech/pegasys/teku/services/powchain/goerli.ssz
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.024 INFO  - A deposit snapshot was read with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.028 INFO  - Loading deposit tree snapshot from database
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.108 INFO  - jetty-11.0.15; built: 2023-04-11T18:37:53.775Z; git: 5bc5e562c8d05c5862505aebe5cf83a61bdbcb96; jvm 17.0.8.1+1
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.111 INFO  - Loaded deposits tree state from snapshot with 313267 deposits and 0x17a3e8af4a09f15ecee4c40c7e3d93aea5fbb7ae6999fce79c5e2fc97eb55b33 execution block hash.
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.206 INFO  - Session workerName=node0
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.224 INFO  - Started i.j.j.@ad89995{/,null,AVAILABLE}
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.300 INFO  - Loading deposits up to Eth1 block 0
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.418 INFO  - x509=X509@2c44ac34(teku-keyapi,h=[localhost, consensus, validator, vc, teku-keyapi-cert],a=[/127.0.0.1],w=[]) for Server@43238071[provider=Conscrypt,keyStore=file:///var/lib/teku/teku-keyapi.keystore,trustStore=null]
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.419 INFO  - Unable to get KeyManagerFactory instance for algorithm [SunX509] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.428 INFO  - Unable to get TrustManagerFactory instance for algorithm [PKIX] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.429 INFO  - Unable to get SSLContext instance for protocol [TLS] on provider [Conscrypt], using default
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.502 INFO  - Started ServerConnector@29353796{SSL, (ssl, http/1.1)}{0.0.0.0:7500}
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.503 INFO  - Started Server@66241e02{STARTING}[11.0.15,sto=0] @61372ms
eth-docker-devel-consensus-1  | 2023-09-18 18:08:19.504 INFO  - Listening on http://localhost:7500/

rolfyone commented 1 year ago

I don't see anything enlightening in logs though re what's happening. I am running on PR 7506.

This one got as far as Listening on http://localhost:5052/, so it started successfully...

Which tbh makes a ton more sense than "engine API". Here it is when web3signer is already up as Teku starts. This one is listening too, so thats a good start...

So there's basically 2 flows:

with config (external-signer set)
if the key isnt present on START, then you'd need to send a HUP to get the key added... currently removal of that key is non trivial (requires restart of teku)
If keymanager is active, this would happen after keys load, but you should still be able to use keymanager to list, just not manage, those keys (and they'd be in the external list)

with just keymanager:

it'll have keys that it needs that were dynamically added at startup, even if the signer isn't on
once signer starts, you'll stop getting production errors
can remove on the fly through the api, or add more on the fly.

I think keymanager is closer to the flow you want...

yorickdowne commented 1 year ago

5052 is cl REST; 7500 is where I have key manager. I assure you key manager was not reachable. When you look at the logs where it works you’ll see separate entries for 5052 and 7500.

yorickdowne commented 1 year ago

Yeah I may need to get back to just keymanager. I was trying to make switching easier for users, but I seem to be making things worse. Just a “register” call is maybe not so bad.

Only that - ah right I remember. This is why I went down this rabbit hole. I had reports from users that Teku would sometimes forget registered keys (remote through keymanager) after a few starts. So I decided to just load them from web3signer instead.

rolfyone commented 1 year ago

I think what i would probably suggest is:

import keys into signer in a single function, and you can check responses to see what got imported successfully
For all keys that successfully imported, add that as a remote key to the CL.

Alternatively, do single calls: 1 key imports to signer, check success/fail do add remote key to CL if it succeeded.

If the add remote fails, its useful to feed to the user still, because they've got a key in their signer thats not being used...

Removal is simple, just remove from CL first, then remove from signer, its possible some ppl may just want to remove from CL and leave in signer depending on what they're trying to do i guess...

The nice thing about this flow is you're adding/removing freely, and no restarts or HUPS are required. also the CL will 'remember' the keys it had on restart, and they'll continue to be mutable...

Hopefully this is helpful, but let me know if we should chat further on this...

yorickdowne commented 1 year ago

OK. I had user reports that with this flow, which I was using previously, Teku might "forget" keys on restart. I'll test and see whether I can reproduce it.

There is a user that is loading keys into web3signer outside of my flow. I'll just need to work with them separately to see whether the register function works. It should if list works.

Let me adjust this and see how it behaves.

rolfyone commented 1 year ago

If teku is forgetting keys that way, it would be very interesting to know how.

External keys are loaded on startup, i'm not 100% sure what happens if the signer is slow, i cant recall, but we persist their details in the keymanager, so if that's not working that's worth understanding.

This is the only flow i can think of which will give you the flexibility that you want if i understand correctly.

yorickdowne commented 1 year ago

Got it. I switched the flow to registration, instead of loading keys on startup. If I get more user reports of Teku "forgetting keys" I'll try and get some logs then.

Consensys / teku