search

ava-labs / avalanchego

Go implementation of an Avalanche node.
https://avax.network
BSD 3-Clause "New" or "Revised" License
2.13k stars 670 forks source link

Restart of the node during bootstrap incorrectly resets logging progress #846

Closed jondoe1337 closed 2 years ago

jondoe1337 commented 3 years ago

Describe the bug When a node is restarted during its bootstrap sequence, the bootstrap is restarted from scratch.

To Reproduce Fresh node + options: --index-enabled --api-admin-enabled --api-ipcs-enabled + restart -> bootstrap is restarted

Expected behavior Bootstrap sequence should continue where it stopped, like all other blockchain nodes do.

Operating System OSX bigSur, reproducible on ubuntu 20.04, inside and outside of docker

StephenButtolph commented 3 years ago

Bootstrapping state is (and has been since v0.1.0) persisted across startups. If you're seeing otherwise, feel free to re-open this issue with some additional details.

jondoe1337 commented 3 years ago

Well, it does not persist. I restarted it during bootstrap because it stopped syncing, but as the logs show - it restarted with the bootstrapping:


     _____               .__                       .__
    /  _  \___  _______  |  | _____    ____   ____ |  |__   ____    ,_ o
   /  /_\  \  \/ /\__  \ |  | \__  \  /    \_/ ___\|  |  \_/ __ \   / //\,
  /    |    \   /  / __ \|  |__/ __ \|   |  \  \___|   Y  \  ___/    \>> |
  \____|__  /\_/  (____  /____(____  /___|  /\___  >___|  /\___  >    \\
          \/           \/          \/     \/     \/     \/     \/
INFO [06-07|14:49:54] main/main.go#51: using build directory at path '/go/src/github.com/ava-labs/avalanchego/build'
INFO [06-07|14:49:57] main/node_manager.go#232: starting latest node version in normal execution mode
INFO [06-07|14:49:59] main/node_manager.go#41: starting node at /go/src/github.com/ava-labs/avalanchego/build/avalanchego-latest/avalanchego-process
INFO [06-07|14:49:59] app/process/process.go#123: bootstrapped with current database version: false
INFO [06-07|14:49:59] node/node.go#876: node version is: avalanche/1.4.6
INFO [06-07|14:49:59] node/node.go#877: node ID is: NodeID-Fv9jnhp53mWt72Jym6UALd26HX1VU7zXa
INFO [06-07|14:49:59] node/node.go#878: current database version: v1.4.5
INFO [06-07|14:49:59] node/node.go#480: initializing API server
INFO [06-07|14:49:59] api/server/server.go#71: API created with allowed origins: [*]
INFO [06-07|14:49:59] node/node.go#711: initializing metrics API
INFO [06-07|14:49:59] api/server/server.go#189: adding route /ext/metrics
INFO [06-07|14:49:59] node/node.go#673: initializing keystore
INFO [06-07|14:49:59] node/node.go#688: initializing keystore API
INFO [06-07|14:49:59] api/server/server.go#189: adding route /ext/keystore
INFO [06-07|14:49:59] node/node.go#665: initializing SharedMemory
INFO [06-07|14:49:59] node/node.go#162: this node's IP is set to: "173.249.8.115:9651"
INFO [06-07|14:49:59] node/node.go#769: initializing Health API
INFO [06-07|14:49:59] api/server/server.go#189: adding route /ext/health
INFO [06-07|14:50:00] api/server/server.go#189: adding route /ext/vm/rWhpuQPF1kb72esV2momhMuTYGkEb1oL29pt2EBXWmSy4kxnT
INFO [06-07|14:50:00] api/server/server.go#189: adding route /ext/vm/jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq
INFO [06-07|14:50:03] node/node.go#730: initializing admin API
INFO [06-07|14:50:03] api/server/server.go#189: adding route /ext/admin
INFO [06-07|14:50:03] node/node.go#743: initializing info API
INFO [06-07|14:50:03] api/server/server.go#189: adding route /ext/info
INFO [06-07|14:50:03] node/node.go#822: initializing ipc API
INFO [06-07|14:50:03] api/server/server.go#189: adding route /ext/ipcs
INFO [06-07|14:50:03] node/node.go#832: initializing aliases
INFO [06-07|14:50:03] node/node.go#466: initializing chains
INFO [06-07|14:50:03] chains/manager.go#230: creating chain:
    ID: 11111111111111111111111111111111LpoYY
    VMID:rWhpuQPF1kb72esV2momhMuTYGkEb1oL29pt2EBXWmSy4kxnT
INFO [06-07|14:50:07] <P Chain> vms/platformvm/vm.go#200: initializing last accepted block as P3L4LgnfuKAhDow8bGSX8uo4jDmkJEF3ZLKKbSW5U3sT178yR
INFO [06-07|14:50:07] <P Chain> snow/engine/snowman/transitive.go#64: initializing consensus engine
INFO [06-07|14:50:07] <P Chain> snow/engine/common/bootstrapper.go#71: Starting bootstrap...
INFO [06-07|14:50:07] indexer/index.go#104: next accepted index 547328
INFO [06-07|14:50:07] api/server/server.go#189: adding route /ext/index/P/block
INFO [06-07|14:50:07] api/server/server.go#95: HTTP API server listening on "0.0.0.0:9650"
INFO [06-07|14:50:07] api/server/server.go#173: adding route /ext/bc/11111111111111111111111111111111LpoYY
INFO [06-07|14:50:07] network/peer.go#676: beacon FYv1Lb29SqMpywYXH7yNkcFAzRF2jvm3K attempting to connect with newer version avalanche/1.4.7. You may want to update your client
INFO [06-07|14:50:07] network/peer.go#676: beacon Dw7tuwxpAmcpvVGp9JzaHAR3REPoJ8f2R attempting to connect with newer version avalanche/1.4.7. You may want to update your client
INFO [06-07|14:50:08] network/peer.go#676: beacon Fv3t2shrpkmvLnvNzcv1rqRKbDAYFnUor attempting to connect with newer version avalanche/1.4.7. You may want to update your client
INFO [06-07|14:50:08] network/peer.go#676: beacon DAtCoXfLT6Y83dgJ7FmQg8eR53hz37J79 attempting to connect with newer version avalanche/1.4.7. You may want to update your client
INFO [06-07|14:50:08] network/peer.go#676: beacon FGRoKnyYKFWYFMb6Xbocf4hKuyCBENgWM attempting to connect with newer version avalanche/1.4.7. You may want to update your client
INFO [06-07|14:50:11] <P Chain> snow/engine/common/bootstrapper.go#300: Bootstrapping started syncing with 1 vertices in the accepted frontier
INFO [06-07|14:50:11] <P Chain> snow/engine/snowman/bootstrap/bootstrapper.go#341: bootstrapping fetched 0 blocks. Executing state transitions...
INFO [06-07|14:50:11] <P Chain> snow/engine/common/queue/jobs.go#165: executed 0 operations
INFO [06-07|14:50:11] chains/manager.go#230: creating chain:
    ID: 2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5
    VMID:mgj786NP7uDwBCcq6YwThhaN8FLyybkCa4zBWTQbNgmK6k9A6
INFO [06-07|14:50:12] <C Chain> snow/engine/snowman/transitive.go#64: initializing consensus engine
INFO [06-07|14:50:12] <C Chain> snow/engine/common/bootstrapper.go#71: Starting bootstrap...
INFO [06-07|14:50:12] indexer/index.go#97: next accepted index 0
INFO [06-07|14:50:12] api/server/server.go#189: adding route /ext/index/C/block
INFO [06-07|14:50:12] chains/manager.go#230: creating chain:
    ID: 2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM
    VMID:jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/avax
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/ws
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/rpc
INFO [06-07|14:50:13] <X Chain> snow/engine/avalanche/transitive.go#72: initializing consensus engine
INFO [06-07|14:50:13] <X Chain> snow/engine/common/bootstrapper.go#71: Starting bootstrap...
INFO [06-07|14:50:13] indexer/index.go#104: next accepted index 2139229
INFO [06-07|14:50:13] api/server/server.go#189: adding route /ext/index/X/vtx
INFO [06-07|14:50:13] indexer/index.go#104: next accepted index 2173983
INFO [06-07|14:50:13] api/server/server.go#189: adding route /ext/index/X/tx
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/wallet
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/events
INFO [06-07|14:50:13] api/server/server.go#173: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM
INFO [06-07|14:50:13] <P Chain> snow/engine/snowman/bootstrap/bootstrapper.go#374: waiting for the remaining chains in this subnet to finish syncing
INFO [06-07|14:50:15] <X Chain> snow/engine/common/bootstrapper.go#300: Bootstrapping started syncing with 1 vertices in the accepted frontier
INFO [06-07|14:50:15] <X Chain> snow/engine/avalanche/bootstrap/bootstrapper.go#428: bootstrapping fetched 0 vertices. Executing transaction state transitions...
INFO [06-07|14:50:15] <X Chain> snow/engine/common/queue/jobs.go#165: executed 0 operations
INFO [06-07|14:50:15] <X Chain> snow/engine/avalanche/bootstrap/bootstrapper.go#439: executing vertex state transitions...
INFO [06-07|14:50:15] <X Chain> snow/engine/common/queue/jobs.go#165: executed 0 operations
INFO [06-07|14:50:15] <X Chain> snow/engine/avalanche/bootstrap/bootstrapper.go#467: waiting for the remaining chains in this subnet to finish syncing
INFO [06-07|14:50:18] <C Chain> snow/engine/common/bootstrapper.go#300: Bootstrapping started syncing with 2 vertices in the accepted frontier
INFO [06-07|14:51:01] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#306: fetched 5000 of 2244532 blocks
INFO [06-07|15:16:44] api/health/service.go#110: Health.getLiveness called
WARN [06-07|15:16:44] api/health/service.go#116: Health.getLiveness is returning an error: {"C":{"message":{"consensus":{},"vm":{}},"timestamp":"2021-06-07T15:16:44.013001876Z","duration":932745,"contiguousFailures":0,"timeOfFirstFailure":null},"P":{"message":{"consensus":{},"vm":{"percentConnected":0.9536436781220649}},"timestamp":"2021-06-07T15:16:39.152468303Z","duration":175025,"contiguousFailures":0,"timeOfFirstFailure":null},"X":{"message":{"consensus":{},"vm":null},"timestamp":"2021-06-07T15:16:44.037471233Z","duration":33861,"contiguousFailures":0,"timeOfFirstFailure":null},"isBootstrapped":{"error":{"message":"primary subnet has not finished bootstrapping"},"timestamp":"2021-06-07T15:16:36.160322277Z","duration":11031,"contiguousFailures":2,"timeOfFirstFailure":"2021-06-07T15:16:26.160122555Z"},"network":{"message":{"connectedPeers":753,"sendFailRate":0.1248408384767667,"sendQueuePortionFull":0,"timeSinceLastMsgReceived":"160.612436ms","timeSinceLastMsgSent":"160.612436ms"},"timestamp":"2021-06-07T15:16:36.160329027Z","duration":101094,"contiguousFailures":0,"timeOfFirstFailure":null},"router":{"message":{"longestRunningRequest":"1.840197801s","msgDropRate":0,"outstandingRequests":26},"timestamp":"2021-06-07T15:16:36.160331497Z","duration":22031,"contiguousFailures":0,"timeOfFirstFailure":null}}

What kind of information do you else need?

3nprob commented 2 years ago

@StephenButtolph Can this be reopened? Observing same behavior here.

v1.6.5 on Docker.

During bootstrapping, the node was restarted here:

INFO [11-16|04:56:00] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 5257500 operations
INFO [11-16|04:57:14] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 5260000 operations
INFO [11-16|04:57:50] /build/node/node.go#1152: shutting down node with exit code 0
INFO [11-16|04:57:50] /build/ipcs/chainipc.go#101: shutting down chain IPCs
INFO [11-16|04:57:50] /build/chains/manager.go#824: shutting down chain manager
INFO [11-16|04:57:50] /build/snow/networking/router/chain_router.go#260: shutting down chain router
INFO [11-16|04:57:50] <P Chain> /build/snow/engine/snowman/transitive.go#154: shutting down consensus engine
INFO [11-16|04:57:50] <X Chain> /build/snow/engine/avalanche/transitive.go#136: shutting down consensus engine
INFO [11-16|04:57:50] <C Chain> /build/snow/engine/common/queue/jobs.go#107: Interrupted execution after executing 5261230 operations
INFO [11-16|04:57:50] <C Chain> /build/snow/engine/snowman/transitive.go#154: shutting down consensus engine
WARN [11-16|04:57:51] /build/health/service.go#133: "C" became unhealthy with: {"message":{"consensus":{},"vm":null},"error":{"message":"rpc error: code = Canceled desc = grpc: the client connection is closing"},"timestamp":"2021-11-15T16:20:17.97022007Z","duration":45453767631537,"contiguousFailures":1,"timeOfFirstFailure":"2021-11-15T16:20:17.97022007Z"}
INFO [11-16|04:57:51] /build/network/network.go#645: shutting down network
INFO [11-16|04:57:51] /build/node/node.go#1176: cleaning up plugin subprocesses
INFO [11-16|04:57:51] /build/node/node.go#1179: finished node shutdown
INFO [11-16|04:57:51] /build/nat/nat.go#152: Unmapped all ports

Then it seems to start from scratch again, re-executing everything from scratch:

INFO [11-16|04:57:57] /build/database/leveldb/db.go#127: leveldb config: {"blockCacheCapacity":12582912,"blockSize":0,"compactionExpandLimitFactor":0,"compactionGPOverlapsFactor":0,"compactionL0Trigger":0,"compactionSourceLimitFactor":0,"compactionTableSize":0,"compactionTableSizeMultiplier":0,"compactionTableSizeMultiplierPerLevel":null,"compactionTotalSize":0,"compactionTotalSizeMultiplier":0,"openFilesCacheCapacity":64,"writeBuffer":6291456,"filterBitsPerKey":10}
INFO [11-16|04:58:01] /build/database/leveldb/db.go#127: leveldb config: {"blockCacheCapacity":12582912,"blockSize":0,"compactionExpandLimitFactor":0,"compactionGPOverlapsFactor":0,"compactionL0Trigger":0,"compactionSourceLimitFactor":0,"compactionTableSize":0,"compactionTableSizeMultiplier":0,"compactionTableSizeMultiplierPerLevel":null,"compactionTotalSize":0,"compactionTotalSizeMultiplier":0,"openFilesCacheCapacity":64,"writeBuffer":6291456,"filterBitsPerKey":10}
INFO [11-16|04:58:01] /build/node/node.go#1050: node version is: avalanche/1.6.5
INFO [11-16|04:58:01] /build/node/node.go#1051: node ID is: NodeID-$MYNODEID
INFO [11-16|04:58:01] /build/node/node.go#1052: current database version: v1.4.5
INFO [11-16|04:58:01] /build/node/node.go#490: initializing API server
INFO [11-16|04:58:01] /build/api/server/server.go#82: API created with allowed origins: [*]
INFO [11-16|04:58:01] /build/node/node.go#802: initializing metrics API
INFO [11-16|04:58:01] /build/node/node.go#767: initializing keystore
INFO [11-16|04:58:01] /build/node/node.go#775: skipping keystore API initialization because it has been disabled
INFO [11-16|04:58:01] /build/node/node.go#759: initializing SharedMemory
INFO [11-16|04:58:01] /build/node/node.go#182: this node's IP is set to: "$MYIP:$MYPORT"
INFO [11-16|04:58:01] /build/node/node.go#908: initializing Health API
INFO [11-16|04:58:01] /build/node/node.go#536: initializing VM aliases
INFO [11-16|04:58:02] /build/node/node.go#822: node config:
{"httpConfig":{"apiConfig":{"authConfig":{"apiRequireAuthToken":false},"indexerConfig":{"indexAPIEnabled":false,"indexAllowIncomplete":false},"ipcConfig":{"ipcAPIEnabled":false,"ipcPath":"/tmp","ipcDefaultChainIDs":null},"adminAPIEnabled":false,"infoAPIEnabled":true,"keystoreAPIEnabled":false,"metricsAPIEnabled":true,"healthAPIEnabled":true},"httpHost":"0.0.0.0","httpPort":$RPCPORT,"httpsEnabled":false,"httpsKeyFile":"","httpsCertFile":"","apiAllowedOrigins":["*"]},"ipConfig":{"ip":{"ip":"$MYIP","port":$MYPORT},"attemptedNATTraversal":false,"dynamicUpdateDuration":300000000000},"stakingConfig":{"uptimeRequirement":0.8,"minValidatorStake":2000000000000,"maxValidatorStake":3000000000000000,"minDelegatorStake":25000000000,"minDelegationFee":20000,"minStakeDuration":1209600000000000,"maxStakeDuration":31536000000000000,"stakeMintingPeriod":31536000000000000,"enableStaking":true,"disabledStakingWeight":100,"stakingKeyPath":"/home/avalanche/.avalanchego/staking/staker.key","stakingCertPath":"/home/avalanche/.avalanchego/staking/staker.crt"},"txFeeConfig":{"txFee":1000000,"createAssetTxFee":10000000,"createSubnetTxFee":1000000000,"createBlockchainTxFee":1000000000},"epochConfig":{"epochFirstTransition":"2020-12-10T19:00:00Z","epochDuration":21600000000000},"bootstrapConfig":{"retryBootstrap":true,"retryBootstrapWarnFrequency":50,"bootstrapBeaconConnectionTimeout":60000000000,"bootstrapMultiputMaxContainersSent":2000,"bootstrapMultiputMaxContainersReceived":2000,"bootstrapMaxTimeGetAncestors":50000000,"bootstrapIDs":["4kCLS16Wy73nt1Zm54jFZsL7Msrv3UCeJ","Dw7tuwxpAmcpvVGp9JzaHAR3REPoJ8f2R","HCw7S2TVbFPDWNBo1GnFWqJ47f9rDJtt1","Hr78Fy8uDYiRYocRYHXp4eLCYeb8x5UuM","BQEo5Fy1FRKLbX51ejqDd14cuSXJKArH2"],"bootstrapIPs":[{"ip":"122.248.199.127","port":9651},{"ip":"52.30.9.211","port":9651},{"ip":"52.47.181.114","port":9651},{"ip":"54.93.182.129","port":9651},{"ip":"3.34.221.73","port":9651}]},"databaseConfig":{"path":"/home/avalanche/db/mainnet","name":"leveldb"},"avaxAssetID":"FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z","networkID":1,"enableAssertions":true,"enableCrypto":true,"healthCheckFreq":30000000000,"networkConfig":{"healthConfig":{"minConnectedPeers":1,"maxTimeSinceMsgReceived":60000000000,"maxTimeSinceMsgSent":60000000000,"maxPortionSendQueueBytesFull":0.9,"maxSendFailRate":0.9,"maxSendFailRateHalflife":10000000000},"peerListGossipConfig":{"peerListSize":20,"peerListGossipSize":50,"peerListStakerGossipFraction":2,"peerListGossipFreq":60000000000},"gossipConfig":{"gossipAcceptedFrontierSize":35,"gossipOnAcceptSize":20,"appGossipNonValidatorSize":0,"appGossipValidatorSize":6},"timeoutConfigs":{"getVersionTimeout":10000000000,"pingPongTimeout":30000000000,"readHandshakeTimeout":15000000000,"peerAliasTimeout":600000000000},"delayConfig":{"initialReconnectDelay":1000000000,"maxReconnectDelay":3600000000000},"throttlerConfig":{"inboundConnUpgradeThrottlerConfig":{"upgradeCooldown":10000000000,"maxRecentConnsUpgraded":2560},"inboundMsgThrottlerConfig":{"vdrAllocSize":33554432,"atLargeAllocSize":6291456,"nodeMaxAtLargeBytes":2097152,"bandwidthRefillRate":524288,"bandwidthMaxBurstRate":2097152,"maxProcessingMsgsPerNode":1024},"outboundMsgThrottlerConfig":{"vdrAllocSize":33554432,"atLargeAllocSize":6291456,"nodeMaxAtLargeBytes":2097152},"maxIncomingConnsPerSec":256},"dialerConfig":{"throttleRps":50,"connectionTimeout":30000000000},"namespace":"avalanche_network","$MYNODEID":"$MYNODEID","myIP":{"ip":"$MYIP","port":$MYPORT},"networkID":1,"maxClockDifference":60000000000,"pingFrequency":22500000000,"allowPrivateIPs":true,"compressionEnabled":true,"whitelistedSubnets":[],"beacons":{},"validators":{},"requireValidatorToConnect":false},"adaptiveTimeoutConfig":{"initialTimeout":5000000000,"minimumTimeout":2000000000,"maximumTimeout":10000000000,"timeoutCoefficient":2,"timeoutHalflife":300000000000},"benchlistConfig":{"threshold":10,"minimumFailingDuration":150000000000,"duration":900000000000,"maxPortion":0.08333333333333333,"peerSummaryEnabled":false},"profilerConfig":{"dir":"/home/avalanche/.avalanchego/profiles","enabled":false,"freq":900000000000,"maxNumFiles":5},"loggingConfig":{"rotationInterval":86400000000000,"fileSize":8388608,"rotationSize":7,"flushSize":1,"disableLogging":false,"disableDisplaying":false,"disableContextualDisplaying":false,"disableFlushOnWrite":false,"assertions":false,"logLevel":"INFO","displayLevel":"INFO","displayHighlight":"PLAIN"},"pluginDir":"/avalanchego/build/plugins","consensusParams":{"k":20,"alpha":15,"betaVirtuous":15,"betaRogue":20,"concurrentRepolls":4,"optimalProcessing":50,"maxOutstandingItems":1024,"maxItemProcessingTime":120000000000,"parents":5,"batchSize":30},"meterVMEnabled":true,"routerHealthConfig":{"maxDropRate":1,"maxDropRateHalflife":10000000000,"maxOutstandingRequests":1024,"maxOutstandingDuration":300000000000,"maxRunTimeRequests":10000000000},"consensusShutdownTimeout":5000000000,"consensusGossipFreq":10000000000,"whitelistedSubnets":[],"subnetConfigs":{},"vmAliases":null}
INFO [11-16|04:58:02] /build/node/node.go#824: skipping admin API initialization because it has been disabled
INFO [11-16|04:58:02] /build/node/node.go#872: initializing info API
INFO [11-16|04:58:02] /build/node/node.go#977: skipping ipc API initialization because it has been disabled
INFO [11-16|04:58:02] /build/node/node.go#990: initializing chain aliases
INFO [11-16|04:58:02] /build/node/node.go#1008: initializing API aliases
INFO [11-16|04:58:02] /build/node/node.go#847: skipping profiler initialization because it has been disabled
INFO [11-16|04:58:02] /build/node/node.go#476: initializing chains
INFO [11-16|04:58:02] /build/chains/manager.go#245: creating chain:
    ID: 11111111111111111111111111111111LpoYY
    VMID:rWhpuQPF1kb72esV2momhMuTYGkEb1oL29pt2EBXWmSy4kxnT
INFO [11-16|04:58:05] <P Chain> /build/vms/platformvm/vm.go#217: initializing last accepted block as 2hfYJqD7aF88cKvhzCfBLV36GwL34y4YBFFi4rCzad4sZEz8vv
INFO [11-16|04:58:05] <P Chain> /build/snow/engine/snowman/transitive.go#62: initializing consensus engine
INFO [11-16|04:58:05] <P Chain> /build/snow/engine/common/bootstrapper.go#82: Starting bootstrap...
INFO [11-16|04:58:05] /build/api/server/server.go#114: HTTP API server listening on "0.0.0.0:$RPCPORT"
INFO [11-16|04:58:15] <P Chain> /build/snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 1 vertices in the accepted frontier
INFO [11-16|04:58:15] <P Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#360: bootstrapping fetched 0 blocks. Executing state transitions...
INFO [11-16|04:58:15] <P Chain> /build/snow/engine/common/queue/jobs.go#168: executed 0 operations
INFO [11-16|04:58:15] /build/chains/manager.go#245: creating chain:
    ID: 2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5
    VMID:mgj786NP7uDwBCcq6YwThhaN8FLyybkCa4zBWTQbNgmK6k9A6
INFO [11-16|04:58:15] <C Chain> /build/snow/engine/snowman/transitive.go#62: initializing consensus engine
INFO [11-16|04:58:15] <C Chain> /build/snow/engine/common/bootstrapper.go#82: Starting bootstrap...
INFO [11-16|04:58:15] /build/chains/manager.go#245: creating chain:
    ID: 2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM
    VMID:jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq
INFO [11-16|04:58:15] <X Chain> /build/vms/avm/vm.go#546: Fee payments are using Asset with Alias: AVAX, AssetID: FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z
INFO [11-16|04:58:15] <X Chain> /build/vms/avm/vm.go#224: address transaction indexing is disabled
INFO [11-16|04:58:15] <X Chain> /build/snow/engine/avalanche/transitive.go#65: initializing consensus engine
INFO [11-16|04:58:15] <C Chain> /build/snow/engine/common/bootstrapper.go#82: Starting bootstrap...
INFO [11-16|04:58:15] /build/chains/manager.go#245: creating chain:
    ID: 2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM
    VMID:jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq
INFO [11-16|04:58:15] <X Chain> /build/vms/avm/vm.go#546: Fee payments are using Asset with Alias: AVAX, AssetID: FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z
INFO [11-16|04:58:15] <X Chain> /build/vms/avm/vm.go#224: address transaction indexing is disabled
INFO [11-16|04:58:15] <X Chain> /build/snow/engine/avalanche/transitive.go#65: initializing consensus engine
INFO [11-16|04:58:15] <X Chain> /build/snow/engine/common/bootstrapper.go#82: Starting bootstrap...
INFO [11-16|04:58:15] <P Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#393: waiting for the remaining chains in this subnet to finish syncing
INFO [11-16|04:58:34] <C Chain> /build/snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 2 vertices in the accepted frontier
INFO [11-16|04:58:34] <X Chain> /build/snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 1 vertices in the accepted frontier
INFO [11-16|04:58:37] <X Chain> /build/snow/engine/avalanche/bootstrap/bootstrapper.go#429: bootstrapping fetched 5 vertices. Executing transaction state transitions...
INFO [11-16|04:58:37] <X Chain> /build/snow/engine/common/queue/jobs.go#168: executed 5 operations
INFO [11-16|04:58:37] <X Chain> /build/snow/engine/avalanche/bootstrap/bootstrapper.go#440: executing vertex state transitions...
INFO [11-16|04:58:37] <X Chain> /build/snow/engine/common/queue/jobs.go#168: executed 5 operations
INFO [11-16|04:58:45] /build/health/service.go#130: "P" became healthy with: {"message":{"consensus":{},"vm":{"percentConnected":0.9925380906607726}},"timestamp":"2021-11-16T04:58:45.594390029Z","duration":80521,"contiguousFailures":0,"timeOfFirstFailure":null}
INFO [11-16|04:59:38] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 5000 of 1747088 blocks
INFO [11-16|05:01:41] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 10000 of 1747088 blocks
INFO [11-16|05:03:48] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 15000 of 1747088 blocks
INFO [11-16|05:06:23] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 20000 of 1747088 blocks
INFO [11-16|05:08:23] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 25000 of 1747088 blocks
INFO [11-16|05:10:42] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 30000 of 1747088 blocks
INFO [11-16|05:12:38] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#325: fetched 35000 of 1747088 blocks
INFO [11-16|05:13:19] <C Chain> /build/snow/engine/snowman/bootstrap/bootstrapper.go#360: bootstrapping fetched 36494 blocks. Executing state transitions...
INFO [11-16|05:14:10] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 2500 operations
INFO [11-16|05:14:57] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 5000 operations
INFO [11-16|05:15:50] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 7500 operations
INFO [11-16|05:16:37] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 10000 operations
INFO [11-16|05:17:28] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 12500 operations
INFO [11-16|05:18:17] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 15000 operations
INFO [11-16|05:19:04] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 17500 operations
INFO [11-16|05:19:51] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 20000 operations
INFO [11-16|05:20:31] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 22500 operations
INFO [11-16|05:21:11] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 25000 operations
INFO [11-16|05:21:54] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 27500 operations
INFO [11-16|05:22:49] <C Chain> /build/snow/engine/common/queue/jobs.go#160: executed 30000 operations

(Or is this simply a case with misleading logging?)

StephenButtolph commented 2 years ago

Restarting a node during bootstrapping doesn't lose the progress of the sync. However, the logs are misleading.

When bootstrapping starts fetching - it calculates how many blocks there are left to fetch by looking at the last accepted (executed) block's height, along with the first block that is fetched.

The engine will then fetch all the blocks from tip towards last accepted block. However, if there is a chain of blocks that have already been fetched, then those are not fetched again.

This has been a low priority logging bug that we just haven't gotten around to fixing. I'll re-open the issue to make it a little more noticeable.

3nprob commented 2 years ago

@StephenButtolph Thanks. Is there anyway to gauge the progress during the "executed X operations" phase (in terms of %, operations, blocks, or bytes)? I've been going over the prometheus metrics and I may be overlooking something but nothing stands out to me.

StephenButtolph commented 2 years ago

Based on your logs you need to wait until the executed log reports having executed 1747088 blocks. There are some metrics that could be looked at, but they are also skewed for the same reason as the incorrect logging.

3nprob commented 2 years ago

For others wondering the same thing, you get the current validated block height with --log-level=trace as of https://github.com/ava-labs/avalanchego/commit/927c72843b66df7953cc7c9ef4dbda7805a0a74e (v1.6.5)