Failed verification during bootstrapping due to time is too far advanced

[Atmannen]

Describe the bug
After running the node in docker (windows 11) on a overkill computer it always fails due to the issue below.

To Reproduce
Start docker container, wait...

Expected behavior
Not to fail.

Screenshots

    /  _  \___  _______  |  | _____    ____   ____ |  |__   ____    ,_ o

   /  /_\  \  \/ /\__  \ |  | \__  \  /    \_/ ___\|  |  \_/ __ \   / //\,

  /    |    \   /  / __ \|  |__/ __ \|   |  \  \___|   Y  \  ___/    \>> |

  \____|__  /\_/  (____  /____(____  /___|  /\___  >___|  /\___  >    \\

          \/           \/          \/     \/     \/     \/     \/

INFO [01-18|11:36:44] database/leveldb/db.go#120: 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}

WARN [01-18|11:36:45] app/process/process.go#119: UPnP or NAT-PMP router attach failed, you may not be listening publicly. Please confirm the settings in your router

INFO [01-18|11:36:45] node/node.go#1062: node version is: avalanche/1.7.3

INFO [01-18|11:36:45] node/node.go#1063: node ID is: NodeID-DsUT4oQUb1K5iTM3BxHuP3CRrsn2vvb6H

INFO [01-18|11:36:45] node/node.go#1064: current database version: v1.4.5

INFO [01-18|11:36:45] node/node.go#490: initializing API server

INFO [01-18|11:36:45] api/server/server.go#82: API created with allowed origins: [*]

INFO [01-18|11:36:45] node/node.go#808: initializing metrics API

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/metrics

INFO [01-18|11:36:45] node/node.go#774: initializing keystore

INFO [01-18|11:36:45] node/node.go#785: initializing keystore API

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/keystore

INFO [01-18|11:36:45] node/node.go#766: initializing SharedMemory

INFO [01-18|11:36:45] node/node.go#181: this node's IP is set to: "172.17.0.2:9651"

INFO [01-18|11:36:45] node/node.go#924: initializing Health API

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/health

INFO [01-18|11:36:45] node/node.go#536: adding the default VM aliases

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/vm/rWhpuQPF1kb72esV2momhMuTYGkEb1oL29pt2EBXWmSy4kxnT

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/vm/jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/vm/mgj786NP7uDwBCcq6YwThhaN8FLyybkCa4zBWTQbNgmK6k9A6/rpc

INFO [01-18|11:36:45] node/node.go#839: node config:

{"httpConfig":{"apiConfig":{"authConfig":{"apiRequireAuthToken":false},"indexerConfig":{"indexAPIEnabled":false,"indexAllowIncomplete":false},"ipcConfig":{"ipcAPIEnabled":false,"ipcPath":"/tmp","ipcDefaultChainIDs":null},"adminAPIEnabled":false,"infoAPIEnabled":true,"keystoreAPIEnabled":true,"metricsAPIEnabled":true,"healthAPIEnabled":true},"httpHost":"127.0.0.1","httpPort":9650,"httpsEnabled":false,"apiAllowedOrigins":["*"],"shutdownTimeout":10000000000,"shutdownWait":0},"ipConfig":{"ip":{"ip":"172.17.0.2","port":9651},"attemptedNATTraversal":true,"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":"/root/.avalanchego/staking/staker.key","stakingCertPath":"/root/.avalanchego/staking/staker.crt"},"txFeeConfig":{"txFee":1000000,"createAssetTxFee":10000000,"createSubnetTxFee":1000000000,"createBlockchainTxFee":1000000000},"bootstrapConfig":{"retryBootstrap":true,"retryBootstrapWarnFrequency":50,"bootstrapBeaconConnectionTimeout":60000000000,"bootstrapMultiputMaxContainersSent":2000,"bootstrapMultiputMaxContainersReceived":2000,"bootstrapMaxTimeGetAncestors":50000000,"bootstrapIDs":["AaxT2P4uuPAHb7vAD8mNvjQ3jgyaV7tu9","Hr78Fy8uDYiRYocRYHXp4eLCYeb8x5UuM","BQEo5Fy1FRKLbX51ejqDd14cuSXJKArH2","A8jypu63CWp76STwKdqP6e9hjL675kdiG","A7GwTSd47AcDVqpTVj7YtxtjHREM33EJw"],"bootstrapIPs":[{"ip":"54.185.87.50","port":9651},{"ip":"54.93.182.129","port":9651},{"ip":"3.34.221.73","port":9651},{"ip":"3.104.107.241","port":9651},{"ip":"3.21.38.33","port":9651}]},"databaseConfig":{"path":"/root/.avalanchego/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":10},"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":"network","myNodeID":"DsUT4oQUb1K5iTM3BxHuP3CRrsn2vvb6H","myIP":{"ip":"172.17.0.2","port":9651},"networkID":1,"maxClockDifference":60000000000,"pingFrequency":22500000000,"allowPrivateIPs":true,"compressionEnabled":true,"whitelistedSubnets":[],"beacons":{},"validators":{},"uptimeMetricFreq":30000000000,"uptimeRequirement":0.8,"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":"/root/.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":"COLORS"},"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":{}}

INFO [01-18|11:36:45] node/node.go#841: skipping admin API initialization because it has been disabled

INFO [01-18|11:36:45] node/node.go#889: initializing info API

INFO [01-18|11:36:45] api/server/server.go#218: adding route /ext/info

INFO [01-18|11:36:45] node/node.go#1001: skipping ipc API initialization because it has been disabled

INFO [01-18|11:36:45] node/node.go#1014: initializing chain aliases

INFO [01-18|11:36:46] node/node.go#1032: initializing API aliases

INFO [01-18|11:36:46] node/node.go#864: skipping profiler initialization because it has been disabled

INFO [01-18|11:36:46] node/node.go#476: initializing chains

INFO [01-18|11:36:46] chains/manager.go#245: creating chain:

    ID: 11111111111111111111111111111111LpoYY

    VMID:rWhpuQPF1kb72esV2momhMuTYGkEb1oL29pt2EBXWmSy4kxnT

INFO [01-18|11:36:48] <P Chain> vms/platformvm/vm.go#223: initializing last accepted block as 2G72CqXkK7Z8qkpvx8RuDBkiXm23fQ1D9AxXBDD4UxUaPjMJ7v

INFO [01-18|11:36:48] <P Chain> snow/engine/snowman/transitive.go#62: initializing consensus engine

INFO [01-18|11:36:48] <P Chain> snow/engine/common/bootstrapper.go#82: Starting bootstrap...

INFO [01-18|11:36:48] api/server/server.go#202: adding route /ext/bc/11111111111111111111111111111111LpoYY

INFO [01-18|11:36:48] api/server/server.go#114: HTTP API server listening on "127.0.0.1:9650"

INFO [01-18|11:36:55] <P Chain> snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 1 vertices in the accepted frontier

INFO [01-18|11:36:56] <P Chain> snow/engine/snowman/bootstrap/bootstrapper.go#361: bootstrapping fetched 862 blocks. Executing state transitions...

INFO [01-18|11:36:58] <P Chain> snow/engine/common/queue/jobs.go#168: executed 864 operations

INFO [01-18|11:36:59] chains/manager.go#245: creating chain:

    ID: 2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5

    VMID:mgj786NP7uDwBCcq6YwThhaN8FLyybkCa4zBWTQbNgmK6k9A6

INFO [01-18|11:36:59] <C Chain> snow/engine/snowman/transitive.go#62: initializing consensus engine

INFO [01-18|11:36:59] <C Chain> snow/engine/common/bootstrapper.go#82: Starting bootstrap...

INFO [01-18|11:36:59] chains/manager.go#245: creating chain:

    ID: 2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM

    VMID:jvYyfQTxGMJLuGWa55kdP2p2zSUYsQ5Raupu4TW34ZAUBAbtq

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/rpc

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/ws

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/avax

INFO [01-18|11:36:59] <X Chain> vms/avm/vm.go#552: Fee payments are using Asset with Alias: AVAX, AssetID: FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z

INFO [01-18|11:36:59] <X Chain> vms/avm/vm.go#230: address transaction indexing is disabled

INFO [01-18|11:36:59] <X Chain> snow/engine/avalanche/transitive.go#65: initializing consensus engine

INFO [01-18|11:36:59] <X Chain> snow/engine/common/bootstrapper.go#82: Starting bootstrap...

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/wallet

INFO [01-18|11:36:59] api/server/server.go#202: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/events

INFO [01-18|11:37:16] <X Chain> snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 1 vertices in the accepted frontier

INFO [01-18|11:37:17] <C Chain> snow/engine/common/bootstrapper.go#272: Bootstrapping started syncing with 1 vertices in the accepted frontier

INFO [01-18|11:37:19] <X Chain> snow/engine/avalanche/bootstrap/bootstrapper.go#430: bootstrapping fetched 1966 vertices. Executing transaction state transitions...

INFO [01-18|11:37:21] <X Chain> snow/engine/common/queue/jobs.go#168: executed 1966 operations

INFO [01-18|11:37:21] <X Chain> snow/engine/avalanche/bootstrap/bootstrapper.go#441: executing vertex state transitions...

INFO [01-18|11:37:22] <X Chain> snow/engine/common/queue/jobs.go#168: executed 1966 operations

INFO [01-18|11:37:28] health/service.go#130: "P" became healthy with: {"message":{"consensus":{},"vm":{"percentConnected":0.9940959632519885}},"timestamp":"2022-01-18T11:37:28.852319083Z","duration":163145,"contiguousFailures":0,"timeOfFirstFailure":null}

INFO [01-18|11:38:02] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#326: fetched 5000 of 3462402 blocks

INFO [01-18|11:38:49] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#326: fetched 10000 of 3462402 blocks

INFO [01-18|11:39:50] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#326: fetched 15000 of 3462402 blocks

INFO [01-18|11:40:56] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#326: fetched 20000 of 3462402 blocks

INFO [01-18|11:41:57] <C Chain> snow/engine/snowman/bootstrap/bootstrapper.go#361: bootstrapping fetched 24439 blocks. Executing state transitions...

INFO [01-18|11:43:32] <C Chain> snow/engine/common/queue/jobs.go#160: executed 2500 operations

INFO [01-18|11:44:53] <C Chain> snow/engine/common/queue/jobs.go#160: executed 5000 operations

INFO [01-18|11:46:21] <C Chain> snow/engine/common/queue/jobs.go#160: executed 7500 operations

INFO [01-18|11:47:38] <C Chain> snow/engine/common/queue/jobs.go#160: executed 10000 operations

INFO [01-18|11:48:48] <C Chain> snow/engine/common/queue/jobs.go#160: executed 12500 operations

INFO [01-18|11:49:52] <C Chain> snow/engine/common/queue/jobs.go#160: executed 15000 operations

INFO [01-18|11:50:51] <C Chain> snow/engine/common/queue/jobs.go#160: executed 17500 operations

INFO [01-18|11:52:03] <C Chain> snow/engine/common/queue/jobs.go#160: executed 20000 operations

INFO [01-18|11:53:09] <C Chain> snow/engine/common/queue/jobs.go#160: executed 22500 operations

INFO [01-18|11:54:17] <C Chain> snow/engine/common/queue/jobs.go#160: executed 25000 operations

INFO [01-18|11:55:27] <C Chain> snow/engine/common/queue/jobs.go#160: executed 27500 operations

INFO [01-18|11:56:40] <C Chain> snow/engine/common/queue/jobs.go#160: executed 30000 operations

INFO [01-18|11:57:52] <C Chain> snow/engine/common/queue/jobs.go#160: executed 32500 operations

INFO [01-18|11:59:08] <C Chain> snow/engine/common/queue/jobs.go#160: executed 35000 operations

INFO [01-18|12:00:27] <C Chain> snow/engine/common/queue/jobs.go#160: executed 37500 operations

INFO [01-18|12:01:40] <C Chain> snow/engine/common/queue/jobs.go#160: executed 40000 operations

INFO [01-18|12:03:07] <C Chain> snow/engine/common/queue/jobs.go#160: executed 42500 operations

INFO [01-18|12:04:27] <C Chain> snow/engine/common/queue/jobs.go#160: executed 45000 operations

INFO [01-18|12:06:02] <C Chain> snow/engine/common/queue/jobs.go#160: executed 47500 operations

INFO [01-18|12:07:24] <C Chain> snow/engine/common/queue/jobs.go#160: executed 50000 operations

INFO [01-18|12:08:36] <C Chain> snow/engine/common/queue/jobs.go#160: executed 52500 operations

INFO [01-18|12:09:43] <C Chain> snow/engine/common/queue/jobs.go#160: executed 55000 operations

INFO [01-18|12:10:56] <C Chain> snow/engine/common/queue/jobs.go#160: executed 57500 operations

INFO [01-18|12:12:20] <C Chain> snow/engine/common/queue/jobs.go#160: executed 60000 operations

INFO [01-18|12:13:35] <C Chain> snow/engine/common/queue/jobs.go#160: executed 62500 operations

INFO [01-18|12:14:52] <C Chain> snow/engine/common/queue/jobs.go#160: executed 65000 operations

INFO [01-18|12:16:12] <C Chain> snow/engine/common/queue/jobs.go#160: executed 67500 operations

INFO [01-18|12:17:29] <C Chain> snow/engine/common/queue/jobs.go#160: executed 70000 operations

INFO [01-18|12:18:43] <C Chain> snow/engine/common/queue/jobs.go#160: executed 72500 operations

INFO [01-18|12:19:51] <C Chain> snow/engine/common/queue/jobs.go#160: executed 75000 operations

INFO [01-18|12:21:07] <C Chain> snow/engine/common/queue/jobs.go#160: executed 77500 operations

INFO [01-18|12:22:21] <C Chain> snow/engine/common/queue/jobs.go#160: executed 80000 operations

INFO [01-18|12:23:37] <C Chain> snow/engine/common/queue/jobs.go#160: executed 82500 operations

INFO [01-18|12:25:02] <C Chain> snow/engine/common/queue/jobs.go#160: executed 85000 operations

INFO [01-18|12:26:19] <C Chain> snow/engine/common/queue/jobs.go#160: executed 87500 operations

INFO [01-18|12:27:39] <C Chain> snow/engine/common/queue/jobs.go#160: executed 90000 operations

INFO [01-18|12:29:01] <C Chain> snow/engine/common/queue/jobs.go#160: executed 92500 operations

INFO [01-18|12:30:13] <C Chain> snow/engine/common/queue/jobs.go#160: executed 95000 operations

INFO [01-18|12:31:28] <C Chain> snow/engine/common/queue/jobs.go#160: executed 97500 operations

INFO [01-18|12:32:37] <C Chain> snow/engine/common/queue/jobs.go#160: executed 100000 operations

INFO [01-18|12:33:40] <C Chain> snow/engine/common/queue/jobs.go#160: executed 102500 operations

INFO [01-18|12:34:44] <C Chain> snow/engine/common/queue/jobs.go#160: executed 105000 operations

INFO [01-18|12:35:55] <C Chain> snow/engine/common/queue/jobs.go#160: executed 107500 operations

INFO [01-18|12:37:11] <C Chain> snow/engine/common/queue/jobs.go#160: executed 110000 operations

INFO [01-18|12:38:27] <C Chain> snow/engine/common/queue/jobs.go#160: executed 112500 operations

INFO [01-18|12:39:16] <C Chain> snow/engine/common/queue/jobs.go#160: executed 115000 operations

INFO [01-18|12:40:08] <C Chain> snow/engine/common/queue/jobs.go#160: executed 117500 operations

INFO [01-18|12:41:14] <C Chain> snow/engine/common/queue/jobs.go#160: executed 120000 operations

INFO [01-18|12:42:12] <C Chain> snow/engine/common/queue/jobs.go#160: executed 122500 operations

INFO [01-18|12:43:09] <C Chain> snow/engine/common/queue/jobs.go#160: executed 125000 operations

INFO [01-18|12:44:12] <C Chain> snow/engine/common/queue/jobs.go#160: executed 127500 operations

INFO [01-18|12:45:13] <C Chain> snow/engine/common/queue/jobs.go#160: executed 130000 operations

INFO [01-18|12:46:01] <C Chain> snow/engine/common/queue/jobs.go#160: executed 132500 operations

INFO [01-18|12:47:01] <C Chain> snow/engine/common/queue/jobs.go#160: executed 135000 operations

INFO [01-18|12:47:51] <C Chain> snow/engine/common/queue/jobs.go#160: executed 137500 operations

INFO [01-18|12:48:43] <C Chain> snow/engine/common/queue/jobs.go#160: executed 140000 operations

INFO [01-18|12:49:36] <C Chain> snow/engine/common/queue/jobs.go#160: executed 142500 operations

INFO [01-18|12:50:24] <C Chain> snow/engine/common/queue/jobs.go#160: executed 145000 operations

INFO [01-18|12:51:11] <C Chain> snow/engine/common/queue/jobs.go#160: executed 147500 operations

INFO [01-18|12:52:06] <C Chain> snow/engine/common/queue/jobs.go#160: executed 150000 operations

INFO [01-18|12:52:52] <C Chain> snow/engine/common/queue/jobs.go#160: executed 152500 operations

INFO [01-18|12:53:48] <C Chain> snow/engine/common/queue/jobs.go#160: executed 155000 operations

INFO [01-18|12:54:46] <C Chain> snow/engine/common/queue/jobs.go#160: executed 157500 operations

INFO [01-18|12:55:40] <C Chain> snow/engine/common/queue/jobs.go#160: executed 160000 operations

INFO [01-18|12:56:36] <C Chain> snow/engine/common/queue/jobs.go#160: executed 162500 operations

INFO [01-18|12:57:39] <C Chain> snow/engine/common/queue/jobs.go#160: executed 165000 operations

ERROR[01-18|12:57:45] <P Chain> snow/engine/snowman/bootstrap/block_job.go#86: block pD3NmvxLZpD42co2TbD5xUX5sHRsbNUjJrqjPQAcd8VF2Vao9 failed verification during bootstrapping due to time is too far advanced

FATAL[01-18|12:57:45] <P Chain> snow/networking/router/handler.go#145: chain shutting down due to error "failed to execute job pD3NmvxLZpD42co2TbD5xUX5sHRsbNUjJrqjPQAcd8VF2Vao9 due to failed to verify block in bootstrapping: time is too far advanced" while processing message: (Op: multi_put, NodeID: NodeID-A8jypu63CWp76STwKdqP6e9hjL675kdiG, RequestID: 955, NumContainers: 688)

INFO [01-18|12:57:45] <P Chain> snow/engine/snowman/transitive.go#154: shutting down consensus engine

INFO [01-18|12:57:45] node/node.go#1164: shutting down node with exit code 1

INFO [01-18|12:57:45] ipcs/chainipc.go#101: shutting down chain IPCs

INFO [01-18|12:57:45] chains/manager.go#828: shutting down chain manager

INFO [01-18|12:57:45] snow/networking/router/chain_router.go#262: shutting down chain router

INFO [01-18|12:57:45] <X Chain> snow/engine/avalanche/transitive.go#136: shutting down consensus engine

INFO [01-18|12:57:45] <C Chain> snow/engine/common/queue/jobs.go#107: Interrupted execution after executing 165233 operations

INFO [01-18|12:57:45] <C Chain> snow/engine/snowman/transitive.go#154: shutting down consensus engine

INFO [01-18|12:57:46] network/network.go#655: shutting down network

WARN [01-18|12:57:46] 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":"2022-01-18T11:42:09.632320093Z","duration":4537229104000,"contiguousFailures":1,"timeOfFirstFailure":"2022-01-18T11:42:09.632320093Z"}

INFO [01-18|12:57:46] node/node.go#1205: cleaning up plugin subprocesses

INFO [01-18|12:57:46] node/node.go#1208: finished node shutdown

INFO [01-18|12:57:46] nat/nat.go#152: Unmapped all ports

Operating System
Windows 11 / Ubuntu 20.04 WSL

Additional context
Processor AMD Ryzen 9 5950X 16-Core Processor, 3401 Mhz, 16 Core(s), 32 Logical Processor(s)
96gb RAM

By submitting this issue I agree to the Terms and Conditions of the Developer Accelerator Program.

[ineron]

I have the same problem.
I have tried all versions 1.7x. Every time I started with a clean base.

INFO [01-25|20:27:53] api/server/server.go#203: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/avax
INFO [01-25|20:27:53] api/server/server.go#203: adding route /ext/bc/2q9e4r6Mu3U68nU1fYjgbR6JvwrRx36CohpAX5UQxse55x1Q5/rpc
INFO [01-25|20:27:53] vms/avm/vm.go#451: initializing with AssetID FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z
INFO [01-25|20:27:53] vms/avm/vm.go#437: Fee payments are using Asset with Alias: AVAX, AssetID: FvwEAhmxKfeiG8SnEvq42hc6whRyY3EFYAvebMqDNDGCgxN5Z
INFO [01-25|20:27:53] vms/avm/vm.go#229: address transaction indexing is disabled
INFO [01-25|20:27:53] snow/engine/avalanche/transitive.go#71: initializing consensus engine
INFO [01-25|20:27:53] snow/engine/avalanche/bootstrap/bootstrapper.go#258: Starting bootstrap...
INFO [01-25|20:27:53] api/server/server.go#203: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM
INFO [01-25|20:27:53] api/server/server.go#203: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/wallet
INFO [01-25|20:27:53] api/server/server.go#203: adding route /ext/bc/2oYMBNV4eNHyqk2fjjV5nVQLDbtmNJzq5s3qs3Lo6ftnC6FByM/events
INFO [01-25|20:28:06] snow/engine/common/bootstrapper.go#235: Bootstrapping started syncing with 1 vertices in the accepted frontier
INFO [01-25|20:28:07] snow/engine/common/bootstrapper.go#235: Bootstrapping started syncing with 3 vertices in the accepted frontier
INFO [01-25|20:28:13] snow/engine/avalanche/bootstrap/bootstrapper.go#388: fetched 5000 vertices
INFO [01-25|20:28:23] snow/engine/avalanche/bootstrap/bootstrapper.go#388: fetched 10000 vertices
INFO [01-25|20:28:27] snow/engine/snowman/bootstrap/bootstrapper.go#383: fetched 5000 of 10051027 blocks. ETA = 11h32m2.559811165s
INFO [01-25|20:28:31] snow/engine/avalanche/bootstrap/bootstrapper.go#388: fetched 15000 vertices
INFO [01-25|20:28:44] snow/engine/avalanche/bootstrap/bootstrapper.go#388: fetched 20000 vertices
INFO [01-25|20:28:54] snow/engine/avalanche/bootstrap/bootstrapper.go#388: fetched 25000 vertices
ERROR[01-25|20:29:00]

snow/engine/snowman/bootstrap/block_job.go#86: block 27tgCaSuDqctiFBugQjEXQ1smMETcUmokRP8RqffELMPUpqyNu failed verification during bootstrapping due to time is too far advanced
FATAL[01-25|20:29:00]

snow/networking/router/handler.go#164: chain shutting down due to error "failed to execute job 27tgCaSuDqctiFBugQjEXQ1smMETcUmokRP8RqffELMPUpqyNu due to failed to verify block in bootstrapping: time is too far advanced" while processing message: (Op: ancestors, NodeID: NodeID-HsBEx3L71EHWSXaE6gvk2VsNntFEZsxqc, RequestID: 3148, NumContainers: 2000)
INFO [01-25|20:29:00]

snow/engine/snowman/transitive.go#282: shutting down consensus engine
INFO [01-25|20:29:00] node/node.go#1218: shutting down node with exit code 1

[StephenButtolph]

"time is too far advanced" is reported due to blocks having a significantly higher timestamp than your local clock. Is your computer's local clock accurate?

[ineron]

I understand what he is complaining about. I do not understand why? The time is synchronized in the UTC. The start blocks cannot be later than the current time.

date

Wed Feb 9 08:08:20 UTC 2022

[ssg]

The same happened to me on my node today. The system clock is accurate. (The NodeID isn't mine). Avalanchego/1.7.8.

INFO [03-23|20:43:51.638] <C Chain> snow/engine/common/queue/jobs.go#173: executed 22500 of 2558449 operations. ETA = 130h37m24s
ERROR[03-23|20:45:12.964] <P Chain> snow/engine/snowman/bootstrap/block_job.go#86: block 21y7npz8pmqb7pbYX9kpfLArXJQQwRBR5Wz2BuEWikbV6xJ9xJ failed verification during bootstrapping due to time is too far advanced
FATAL[03-23|20:45:12.964] <P Chain> snow/networking/handler/handler.go#218: shutting down chain due to unexpected error: failed to execute job 21y7npz8pmqb7pbYX9kpfLArXJQQwRBR5Wz2BuEWikbV6xJ9xJ due to failed to verify block in bootstrapping: time is too far advanced while processing sync message: (Op: ancestors, NodeID: NodeID-GSgaA47umS1px2ohVjodW9621Ks63xDxD, RequestID: 870, NumContainers: 1375)

[darioush]

This issue was fixed in https://github.com/ava-labs/avalanchego/releases/tag/v1.7.18