You can not select more than 25 topics Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.

1096 lines
30 KiB

statesync: remove deadlock on init fail (#7029) When statesync is stopped during shutdown, it has the possibility of deadlocking. A dump of goroutines reveals that this is related to the peerUpdates channel not returning anything on its `Done()` channel when `OnStop` is called. As this is occuring, `processPeerUpdate` is attempting to acquire the reactor lock. It appears that this lock can never be acquired. I looked for the places where the lock may remain locked accidentally and cleaned them up in hopes to eradicate the issue. Dumps of the relevant goroutines may be found below. Note that the line numbers below are relative to the code in the `v0.35.0-rc1` tag. ``` goroutine 36 [chan receive]: github.com/tendermint/tendermint/internal/statesync.(*Reactor).OnStop(0xc00058f200) github.com/tendermint/tendermint/internal/statesync/reactor.go:243 +0x117 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc00058f200, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/node.(*nodeImpl).OnStop(0xc0001ea240) github.com/tendermint/tendermint/node/node.go:769 +0x132 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc0001ea240, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/cmd/tendermint/commands.NewRunNodeCmd.func1.1() github.com/tendermint/tendermint/cmd/tendermint/commands/run_node.go:143 +0x62 github.com/tendermint/tendermint/libs/os.TrapSignal.func1(0xc000629500, 0x7fdb52f96358, 0xc0002b5030, 0xc00000daa0) github.com/tendermint/tendermint/libs/os/os.go:26 +0x102 created by github.com/tendermint/tendermint/libs/os.TrapSignal github.com/tendermint/tendermint/libs/os/os.go:22 +0xe6 goroutine 188 [semacquire]: sync.runtime_SemacquireMutex(0xc00026b1cc, 0x0, 0x1) runtime/sema.go:71 +0x47 sync.(*Mutex).lockSlow(0xc00026b1c8) sync/mutex.go:138 +0x105 sync.(*Mutex).Lock(...) sync/mutex.go:81 sync.(*RWMutex).Lock(0xc00026b1c8) sync/rwmutex.go:111 +0x90 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdate(0xc00026b080, 0xc000650008, 0x28, 0x124de90, 0x4) github.com/tendermint/tendermint/internal/statesync/reactor.go:849 +0x1a5 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdates(0xc00026b080) github.com/tendermint/tendermint/internal/statesync/reactor.go:883 +0xab created by github.com/tendermint/tendermint/internal/statesync.(*Reactor.OnStart github.com/tendermint/tendermint/internal/statesync/reactor.go:219 +0xcd) ```
3 years ago
statesync: remove deadlock on init fail (#7029) When statesync is stopped during shutdown, it has the possibility of deadlocking. A dump of goroutines reveals that this is related to the peerUpdates channel not returning anything on its `Done()` channel when `OnStop` is called. As this is occuring, `processPeerUpdate` is attempting to acquire the reactor lock. It appears that this lock can never be acquired. I looked for the places where the lock may remain locked accidentally and cleaned them up in hopes to eradicate the issue. Dumps of the relevant goroutines may be found below. Note that the line numbers below are relative to the code in the `v0.35.0-rc1` tag. ``` goroutine 36 [chan receive]: github.com/tendermint/tendermint/internal/statesync.(*Reactor).OnStop(0xc00058f200) github.com/tendermint/tendermint/internal/statesync/reactor.go:243 +0x117 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc00058f200, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/node.(*nodeImpl).OnStop(0xc0001ea240) github.com/tendermint/tendermint/node/node.go:769 +0x132 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc0001ea240, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/cmd/tendermint/commands.NewRunNodeCmd.func1.1() github.com/tendermint/tendermint/cmd/tendermint/commands/run_node.go:143 +0x62 github.com/tendermint/tendermint/libs/os.TrapSignal.func1(0xc000629500, 0x7fdb52f96358, 0xc0002b5030, 0xc00000daa0) github.com/tendermint/tendermint/libs/os/os.go:26 +0x102 created by github.com/tendermint/tendermint/libs/os.TrapSignal github.com/tendermint/tendermint/libs/os/os.go:22 +0xe6 goroutine 188 [semacquire]: sync.runtime_SemacquireMutex(0xc00026b1cc, 0x0, 0x1) runtime/sema.go:71 +0x47 sync.(*Mutex).lockSlow(0xc00026b1c8) sync/mutex.go:138 +0x105 sync.(*Mutex).Lock(...) sync/mutex.go:81 sync.(*RWMutex).Lock(0xc00026b1c8) sync/rwmutex.go:111 +0x90 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdate(0xc00026b080, 0xc000650008, 0x28, 0x124de90, 0x4) github.com/tendermint/tendermint/internal/statesync/reactor.go:849 +0x1a5 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdates(0xc00026b080) github.com/tendermint/tendermint/internal/statesync/reactor.go:883 +0xab created by github.com/tendermint/tendermint/internal/statesync.(*Reactor.OnStart github.com/tendermint/tendermint/internal/statesync/reactor.go:219 +0xcd) ```
3 years ago
statesync: remove deadlock on init fail (#7029) When statesync is stopped during shutdown, it has the possibility of deadlocking. A dump of goroutines reveals that this is related to the peerUpdates channel not returning anything on its `Done()` channel when `OnStop` is called. As this is occuring, `processPeerUpdate` is attempting to acquire the reactor lock. It appears that this lock can never be acquired. I looked for the places where the lock may remain locked accidentally and cleaned them up in hopes to eradicate the issue. Dumps of the relevant goroutines may be found below. Note that the line numbers below are relative to the code in the `v0.35.0-rc1` tag. ``` goroutine 36 [chan receive]: github.com/tendermint/tendermint/internal/statesync.(*Reactor).OnStop(0xc00058f200) github.com/tendermint/tendermint/internal/statesync/reactor.go:243 +0x117 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc00058f200, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/node.(*nodeImpl).OnStop(0xc0001ea240) github.com/tendermint/tendermint/node/node.go:769 +0x132 github.com/tendermint/tendermint/libs/service.(*BaseService).Stop(0xc0001ea240, 0x0, 0x0) github.com/tendermint/tendermint/libs/service/service.go:171 +0x323 github.com/tendermint/tendermint/cmd/tendermint/commands.NewRunNodeCmd.func1.1() github.com/tendermint/tendermint/cmd/tendermint/commands/run_node.go:143 +0x62 github.com/tendermint/tendermint/libs/os.TrapSignal.func1(0xc000629500, 0x7fdb52f96358, 0xc0002b5030, 0xc00000daa0) github.com/tendermint/tendermint/libs/os/os.go:26 +0x102 created by github.com/tendermint/tendermint/libs/os.TrapSignal github.com/tendermint/tendermint/libs/os/os.go:22 +0xe6 goroutine 188 [semacquire]: sync.runtime_SemacquireMutex(0xc00026b1cc, 0x0, 0x1) runtime/sema.go:71 +0x47 sync.(*Mutex).lockSlow(0xc00026b1c8) sync/mutex.go:138 +0x105 sync.(*Mutex).Lock(...) sync/mutex.go:81 sync.(*RWMutex).Lock(0xc00026b1c8) sync/rwmutex.go:111 +0x90 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdate(0xc00026b080, 0xc000650008, 0x28, 0x124de90, 0x4) github.com/tendermint/tendermint/internal/statesync/reactor.go:849 +0x1a5 github.com/tendermint/tendermint/internal/statesync.(*Reactor).processPeerUpdates(0xc00026b080) github.com/tendermint/tendermint/internal/statesync/reactor.go:883 +0xab created by github.com/tendermint/tendermint/internal/statesync.(*Reactor.OnStart github.com/tendermint/tendermint/internal/statesync/reactor.go:219 +0xcd) ```
3 years ago
  1. package statesync
  2. import (
  3. "bytes"
  4. "context"
  5. "errors"
  6. "fmt"
  7. "reflect"
  8. "runtime/debug"
  9. "sort"
  10. "time"
  11. abci "github.com/tendermint/tendermint/abci/types"
  12. "github.com/tendermint/tendermint/config"
  13. tmsync "github.com/tendermint/tendermint/internal/libs/sync"
  14. "github.com/tendermint/tendermint/internal/p2p"
  15. "github.com/tendermint/tendermint/internal/proxy"
  16. sm "github.com/tendermint/tendermint/internal/state"
  17. "github.com/tendermint/tendermint/internal/store"
  18. "github.com/tendermint/tendermint/libs/log"
  19. "github.com/tendermint/tendermint/libs/service"
  20. "github.com/tendermint/tendermint/light"
  21. "github.com/tendermint/tendermint/light/provider"
  22. ssproto "github.com/tendermint/tendermint/proto/tendermint/statesync"
  23. "github.com/tendermint/tendermint/types"
  24. )
  25. var (
  26. _ service.Service = (*Reactor)(nil)
  27. _ p2p.Wrapper = (*ssproto.Message)(nil)
  28. )
  29. const (
  30. // SnapshotChannel exchanges snapshot metadata
  31. SnapshotChannel = p2p.ChannelID(0x60)
  32. // ChunkChannel exchanges chunk contents
  33. ChunkChannel = p2p.ChannelID(0x61)
  34. // LightBlockChannel exchanges light blocks
  35. LightBlockChannel = p2p.ChannelID(0x62)
  36. // ParamsChannel exchanges consensus params
  37. ParamsChannel = p2p.ChannelID(0x63)
  38. // recentSnapshots is the number of recent snapshots to send and receive per peer.
  39. recentSnapshots = 10
  40. // snapshotMsgSize is the maximum size of a snapshotResponseMessage
  41. snapshotMsgSize = int(4e6) // ~4MB
  42. // chunkMsgSize is the maximum size of a chunkResponseMessage
  43. chunkMsgSize = int(16e6) // ~16MB
  44. // lightBlockMsgSize is the maximum size of a lightBlockResponseMessage
  45. lightBlockMsgSize = int(1e7) // ~1MB
  46. // paramMsgSize is the maximum size of a paramsResponseMessage
  47. paramMsgSize = int(1e5) // ~100kb
  48. // lightBlockResponseTimeout is how long the dispatcher waits for a peer to
  49. // return a light block
  50. lightBlockResponseTimeout = 10 * time.Second
  51. // consensusParamsResponseTimeout is the time the p2p state provider waits
  52. // before performing a secondary call
  53. consensusParamsResponseTimeout = 5 * time.Second
  54. // maxLightBlockRequestRetries is the amount of retries acceptable before
  55. // the backfill process aborts
  56. maxLightBlockRequestRetries = 20
  57. )
  58. func GetChannelDescriptors() []*p2p.ChannelDescriptor {
  59. return []*p2p.ChannelDescriptor{
  60. {
  61. ID: SnapshotChannel,
  62. MessageType: new(ssproto.Message),
  63. Priority: 6,
  64. SendQueueCapacity: 10,
  65. RecvMessageCapacity: snapshotMsgSize,
  66. RecvBufferCapacity: 128,
  67. },
  68. {
  69. ID: ChunkChannel,
  70. Priority: 3,
  71. MessageType: new(ssproto.Message),
  72. SendQueueCapacity: 4,
  73. RecvMessageCapacity: chunkMsgSize,
  74. RecvBufferCapacity: 128,
  75. },
  76. {
  77. ID: LightBlockChannel,
  78. MessageType: new(ssproto.Message),
  79. Priority: 5,
  80. SendQueueCapacity: 10,
  81. RecvMessageCapacity: lightBlockMsgSize,
  82. RecvBufferCapacity: 128,
  83. },
  84. {
  85. ID: ParamsChannel,
  86. MessageType: new(ssproto.Message),
  87. Priority: 2,
  88. SendQueueCapacity: 10,
  89. RecvMessageCapacity: paramMsgSize,
  90. RecvBufferCapacity: 128,
  91. },
  92. }
  93. }
  94. // Metricer defines an interface used for the rpc sync info query, please see statesync.metrics
  95. // for the details.
  96. type Metricer interface {
  97. TotalSnapshots() int64
  98. ChunkProcessAvgTime() time.Duration
  99. SnapshotHeight() int64
  100. SnapshotChunksCount() int64
  101. SnapshotChunksTotal() int64
  102. BackFilledBlocks() int64
  103. BackFillBlocksTotal() int64
  104. }
  105. // Reactor handles state sync, both restoring snapshots for the local node and
  106. // serving snapshots for other nodes.
  107. type Reactor struct {
  108. service.BaseService
  109. chainID string
  110. initialHeight int64
  111. cfg config.StateSyncConfig
  112. stateStore sm.Store
  113. blockStore *store.BlockStore
  114. conn proxy.AppConnSnapshot
  115. connQuery proxy.AppConnQuery
  116. tempDir string
  117. snapshotCh *p2p.Channel
  118. chunkCh *p2p.Channel
  119. blockCh *p2p.Channel
  120. paramsCh *p2p.Channel
  121. peerUpdates *p2p.PeerUpdates
  122. closeCh chan struct{}
  123. // Dispatcher is used to multiplex light block requests and responses over multiple
  124. // peers used by the p2p state provider and in reverse sync.
  125. dispatcher *Dispatcher
  126. peers *peerList
  127. // These will only be set when a state sync is in progress. It is used to feed
  128. // received snapshots and chunks into the syncer and manage incoming and outgoing
  129. // providers.
  130. mtx tmsync.RWMutex
  131. syncer *syncer
  132. providers map[types.NodeID]*BlockProvider
  133. stateProvider StateProvider
  134. metrics *Metrics
  135. backfillBlockTotal int64
  136. backfilledBlocks int64
  137. }
  138. // NewReactor returns a reference to a new state sync reactor, which implements
  139. // the service.Service interface. It accepts a logger, connections for snapshots
  140. // and querying, references to p2p Channels and a channel to listen for peer
  141. // updates on. Note, the reactor will close all p2p Channels when stopping.
  142. func NewReactor(
  143. chainID string,
  144. initialHeight int64,
  145. cfg config.StateSyncConfig,
  146. logger log.Logger,
  147. conn proxy.AppConnSnapshot,
  148. connQuery proxy.AppConnQuery,
  149. snapshotCh, chunkCh, blockCh, paramsCh *p2p.Channel,
  150. peerUpdates *p2p.PeerUpdates,
  151. stateStore sm.Store,
  152. blockStore *store.BlockStore,
  153. tempDir string,
  154. ssMetrics *Metrics,
  155. ) *Reactor {
  156. r := &Reactor{
  157. chainID: chainID,
  158. initialHeight: initialHeight,
  159. cfg: cfg,
  160. conn: conn,
  161. connQuery: connQuery,
  162. snapshotCh: snapshotCh,
  163. chunkCh: chunkCh,
  164. blockCh: blockCh,
  165. paramsCh: paramsCh,
  166. peerUpdates: peerUpdates,
  167. closeCh: make(chan struct{}),
  168. tempDir: tempDir,
  169. stateStore: stateStore,
  170. blockStore: blockStore,
  171. peers: newPeerList(),
  172. dispatcher: NewDispatcher(blockCh.Out),
  173. providers: make(map[types.NodeID]*BlockProvider),
  174. metrics: ssMetrics,
  175. }
  176. r.BaseService = *service.NewBaseService(logger, "StateSync", r)
  177. return r
  178. }
  179. // OnStart starts separate go routines for each p2p Channel and listens for
  180. // envelopes on each. In addition, it also listens for peer updates and handles
  181. // messages on that p2p channel accordingly. Note, we do not launch a go-routine to
  182. // handle individual envelopes as to not have to deal with bounding workers or pools.
  183. // The caller must be sure to execute OnStop to ensure the outbound p2p Channels are
  184. // closed. No error is returned.
  185. func (r *Reactor) OnStart(ctx context.Context) error {
  186. go r.processCh(ctx, r.snapshotCh, "snapshot")
  187. go r.processCh(ctx, r.chunkCh, "chunk")
  188. go r.processCh(ctx, r.blockCh, "light block")
  189. go r.processCh(ctx, r.paramsCh, "consensus params")
  190. go r.processPeerUpdates(ctx)
  191. return nil
  192. }
  193. // OnStop stops the reactor by signaling to all spawned goroutines to exit and
  194. // blocking until they all exit.
  195. func (r *Reactor) OnStop() {
  196. // tell the dispatcher to stop sending any more requests
  197. r.dispatcher.Close()
  198. // wait for any remaining requests to complete
  199. <-r.dispatcher.Done()
  200. // Close closeCh to signal to all spawned goroutines to gracefully exit. All
  201. // p2p Channels should execute Close().
  202. close(r.closeCh)
  203. <-r.peerUpdates.Done()
  204. }
  205. // Sync runs a state sync, fetching snapshots and providing chunks to the
  206. // application. At the close of the operation, Sync will bootstrap the state
  207. // store and persist the commit at that height so that either consensus or
  208. // blocksync can commence. It will then proceed to backfill the necessary amount
  209. // of historical blocks before participating in consensus
  210. func (r *Reactor) Sync(ctx context.Context) (sm.State, error) {
  211. // We need at least two peers (for cross-referencing of light blocks) before we can
  212. // begin state sync
  213. if err := r.waitForEnoughPeers(ctx, 2); err != nil {
  214. return sm.State{}, err
  215. }
  216. r.mtx.Lock()
  217. if r.syncer != nil {
  218. r.mtx.Unlock()
  219. return sm.State{}, errors.New("a state sync is already in progress")
  220. }
  221. if err := r.initStateProvider(ctx, r.chainID, r.initialHeight); err != nil {
  222. r.mtx.Unlock()
  223. return sm.State{}, err
  224. }
  225. r.syncer = newSyncer(
  226. r.cfg,
  227. r.Logger,
  228. r.conn,
  229. r.connQuery,
  230. r.stateProvider,
  231. r.snapshotCh.Out,
  232. r.chunkCh.Out,
  233. ctx.Done(),
  234. r.tempDir,
  235. r.metrics,
  236. )
  237. r.mtx.Unlock()
  238. defer func() {
  239. r.mtx.Lock()
  240. // reset syncing objects at the close of Sync
  241. r.syncer = nil
  242. r.stateProvider = nil
  243. r.mtx.Unlock()
  244. }()
  245. requestSnapshotsHook := func() {
  246. // request snapshots from all currently connected peers
  247. msg := p2p.Envelope{
  248. Broadcast: true,
  249. Message: &ssproto.SnapshotsRequest{},
  250. }
  251. select {
  252. case <-ctx.Done():
  253. case <-r.closeCh:
  254. case r.snapshotCh.Out <- msg:
  255. }
  256. }
  257. state, commit, err := r.syncer.SyncAny(ctx, r.cfg.DiscoveryTime, requestSnapshotsHook)
  258. if err != nil {
  259. return sm.State{}, err
  260. }
  261. err = r.stateStore.Bootstrap(state)
  262. if err != nil {
  263. return sm.State{}, fmt.Errorf("failed to bootstrap node with new state: %w", err)
  264. }
  265. err = r.blockStore.SaveSeenCommit(state.LastBlockHeight, commit)
  266. if err != nil {
  267. return sm.State{}, fmt.Errorf("failed to store last seen commit: %w", err)
  268. }
  269. err = r.Backfill(ctx, state)
  270. if err != nil {
  271. r.Logger.Error("backfill failed. Proceeding optimistically...", "err", err)
  272. }
  273. return state, nil
  274. }
  275. // Backfill sequentially fetches, verifies and stores light blocks in reverse
  276. // order. It does not stop verifying blocks until reaching a block with a height
  277. // and time that is less or equal to the stopHeight and stopTime. The
  278. // trustedBlockID should be of the header at startHeight.
  279. func (r *Reactor) Backfill(ctx context.Context, state sm.State) error {
  280. params := state.ConsensusParams.Evidence
  281. stopHeight := state.LastBlockHeight - params.MaxAgeNumBlocks
  282. stopTime := state.LastBlockTime.Add(-params.MaxAgeDuration)
  283. // ensure that stop height doesn't go below the initial height
  284. if stopHeight < state.InitialHeight {
  285. stopHeight = state.InitialHeight
  286. // this essentially makes stop time a void criteria for termination
  287. stopTime = state.LastBlockTime
  288. }
  289. return r.backfill(
  290. ctx,
  291. state.ChainID,
  292. state.LastBlockHeight,
  293. stopHeight,
  294. state.InitialHeight,
  295. state.LastBlockID,
  296. stopTime,
  297. )
  298. }
  299. func (r *Reactor) backfill(
  300. ctx context.Context,
  301. chainID string,
  302. startHeight, stopHeight, initialHeight int64,
  303. trustedBlockID types.BlockID,
  304. stopTime time.Time,
  305. ) error {
  306. r.Logger.Info("starting backfill process...", "startHeight", startHeight,
  307. "stopHeight", stopHeight, "stopTime", stopTime, "trustedBlockID", trustedBlockID)
  308. r.backfillBlockTotal = startHeight - stopHeight + 1
  309. r.metrics.BackFillBlocksTotal.Set(float64(r.backfillBlockTotal))
  310. const sleepTime = 1 * time.Second
  311. var (
  312. lastValidatorSet *types.ValidatorSet
  313. lastChangeHeight = startHeight
  314. )
  315. queue := newBlockQueue(startHeight, stopHeight, initialHeight, stopTime, maxLightBlockRequestRetries)
  316. // fetch light blocks across four workers. The aim with deploying concurrent
  317. // workers is to equate the network messaging time with the verification
  318. // time. Ideally we want the verification process to never have to be
  319. // waiting on blocks. If it takes 4s to retrieve a block and 1s to verify
  320. // it, then steady state involves four workers.
  321. for i := 0; i < int(r.cfg.Fetchers); i++ {
  322. ctxWithCancel, cancel := context.WithCancel(ctx)
  323. defer cancel()
  324. go func() {
  325. for {
  326. select {
  327. case <-ctx.Done():
  328. return
  329. case height := <-queue.nextHeight():
  330. // pop the next peer of the list to send a request to
  331. peer := r.peers.Pop(ctx)
  332. r.Logger.Debug("fetching next block", "height", height, "peer", peer)
  333. subCtx, cancel := context.WithTimeout(ctxWithCancel, lightBlockResponseTimeout)
  334. defer cancel()
  335. lb, err := func() (*types.LightBlock, error) {
  336. defer cancel()
  337. // request the light block with a timeout
  338. return r.dispatcher.LightBlock(subCtx, height, peer)
  339. }()
  340. // once the peer has returned a value, add it back to the peer list to be used again
  341. r.peers.Append(peer)
  342. if errors.Is(err, context.Canceled) {
  343. return
  344. }
  345. if err != nil {
  346. queue.retry(height)
  347. if errors.Is(err, errNoConnectedPeers) {
  348. r.Logger.Info("backfill: no connected peers to fetch light blocks from; sleeping...",
  349. "sleepTime", sleepTime)
  350. time.Sleep(sleepTime)
  351. } else {
  352. // we don't punish the peer as it might just have not responded in time
  353. r.Logger.Info("backfill: error with fetching light block",
  354. "height", height, "err", err)
  355. }
  356. continue
  357. }
  358. if lb == nil {
  359. r.Logger.Info("backfill: peer didn't have block, fetching from another peer", "height", height)
  360. queue.retry(height)
  361. // As we are fetching blocks backwards, if this node doesn't have the block it likely doesn't
  362. // have any prior ones, thus we remove it from the peer list.
  363. r.peers.Remove(peer)
  364. continue
  365. }
  366. // run a validate basic. This checks the validator set and commit
  367. // hashes line up
  368. err = lb.ValidateBasic(chainID)
  369. if err != nil || lb.Height != height {
  370. r.Logger.Info("backfill: fetched light block failed validate basic, removing peer...",
  371. "err", err, "height", height)
  372. queue.retry(height)
  373. r.blockCh.Error <- p2p.PeerError{
  374. NodeID: peer,
  375. Err: fmt.Errorf("received invalid light block: %w", err),
  376. }
  377. continue
  378. }
  379. // add block to queue to be verified
  380. queue.add(lightBlockResponse{
  381. block: lb,
  382. peer: peer,
  383. })
  384. r.Logger.Debug("backfill: added light block to processing queue", "height", height)
  385. case <-queue.done():
  386. return
  387. }
  388. }
  389. }()
  390. }
  391. // verify all light blocks
  392. for {
  393. select {
  394. case <-r.closeCh:
  395. queue.close()
  396. return nil
  397. case <-ctx.Done():
  398. queue.close()
  399. return nil
  400. case resp := <-queue.verifyNext():
  401. // validate the header hash. We take the last block id of the
  402. // previous header (i.e. one height above) as the trusted hash which
  403. // we equate to. ValidatorsHash and CommitHash have already been
  404. // checked in the `ValidateBasic`
  405. if w, g := trustedBlockID.Hash, resp.block.Hash(); !bytes.Equal(w, g) {
  406. r.Logger.Info("received invalid light block. header hash doesn't match trusted LastBlockID",
  407. "trustedHash", w, "receivedHash", g, "height", resp.block.Height)
  408. r.blockCh.Error <- p2p.PeerError{
  409. NodeID: resp.peer,
  410. Err: fmt.Errorf("received invalid light block. Expected hash %v, got: %v", w, g),
  411. }
  412. queue.retry(resp.block.Height)
  413. continue
  414. }
  415. // save the signed headers
  416. err := r.blockStore.SaveSignedHeader(resp.block.SignedHeader, trustedBlockID)
  417. if err != nil {
  418. return err
  419. }
  420. // check if there has been a change in the validator set
  421. if lastValidatorSet != nil && !bytes.Equal(resp.block.Header.ValidatorsHash, resp.block.Header.NextValidatorsHash) {
  422. // save all the heights that the last validator set was the same
  423. err = r.stateStore.SaveValidatorSets(resp.block.Height+1, lastChangeHeight, lastValidatorSet)
  424. if err != nil {
  425. return err
  426. }
  427. // update the lastChangeHeight
  428. lastChangeHeight = resp.block.Height
  429. }
  430. trustedBlockID = resp.block.LastBlockID
  431. queue.success()
  432. r.Logger.Info("backfill: verified and stored light block", "height", resp.block.Height)
  433. lastValidatorSet = resp.block.ValidatorSet
  434. r.backfilledBlocks++
  435. r.metrics.BackFilledBlocks.Add(1)
  436. // The block height might be less than the stopHeight because of the stopTime condition
  437. // hasn't been fulfilled.
  438. if resp.block.Height < stopHeight {
  439. r.backfillBlockTotal++
  440. r.metrics.BackFillBlocksTotal.Set(float64(r.backfillBlockTotal))
  441. }
  442. case <-queue.done():
  443. if err := queue.error(); err != nil {
  444. return err
  445. }
  446. // save the final batch of validators
  447. if err := r.stateStore.SaveValidatorSets(queue.terminal.Height, lastChangeHeight, lastValidatorSet); err != nil {
  448. return err
  449. }
  450. r.Logger.Info("successfully completed backfill process", "endHeight", queue.terminal.Height)
  451. return nil
  452. }
  453. }
  454. }
  455. // handleSnapshotMessage handles envelopes sent from peers on the
  456. // SnapshotChannel. It returns an error only if the Envelope.Message is unknown
  457. // for this channel. This should never be called outside of handleMessage.
  458. func (r *Reactor) handleSnapshotMessage(envelope p2p.Envelope) error {
  459. logger := r.Logger.With("peer", envelope.From)
  460. switch msg := envelope.Message.(type) {
  461. case *ssproto.SnapshotsRequest:
  462. snapshots, err := r.recentSnapshots(recentSnapshots)
  463. if err != nil {
  464. logger.Error("failed to fetch snapshots", "err", err)
  465. return nil
  466. }
  467. for _, snapshot := range snapshots {
  468. logger.Info(
  469. "advertising snapshot",
  470. "height", snapshot.Height,
  471. "format", snapshot.Format,
  472. "peer", envelope.From,
  473. )
  474. r.snapshotCh.Out <- p2p.Envelope{
  475. To: envelope.From,
  476. Message: &ssproto.SnapshotsResponse{
  477. Height: snapshot.Height,
  478. Format: snapshot.Format,
  479. Chunks: snapshot.Chunks,
  480. Hash: snapshot.Hash,
  481. Metadata: snapshot.Metadata,
  482. },
  483. }
  484. }
  485. case *ssproto.SnapshotsResponse:
  486. r.mtx.RLock()
  487. defer r.mtx.RUnlock()
  488. if r.syncer == nil {
  489. logger.Debug("received unexpected snapshot; no state sync in progress")
  490. return nil
  491. }
  492. logger.Info("received snapshot", "height", msg.Height, "format", msg.Format)
  493. _, err := r.syncer.AddSnapshot(envelope.From, &snapshot{
  494. Height: msg.Height,
  495. Format: msg.Format,
  496. Chunks: msg.Chunks,
  497. Hash: msg.Hash,
  498. Metadata: msg.Metadata,
  499. })
  500. if err != nil {
  501. logger.Error(
  502. "failed to add snapshot",
  503. "height", msg.Height,
  504. "format", msg.Format,
  505. "err", err,
  506. "channel", r.snapshotCh.ID,
  507. )
  508. return nil
  509. }
  510. logger.Info("added snapshot", "height", msg.Height, "format", msg.Format)
  511. default:
  512. return fmt.Errorf("received unknown message: %T", msg)
  513. }
  514. return nil
  515. }
  516. // handleChunkMessage handles envelopes sent from peers on the ChunkChannel.
  517. // It returns an error only if the Envelope.Message is unknown for this channel.
  518. // This should never be called outside of handleMessage.
  519. func (r *Reactor) handleChunkMessage(envelope p2p.Envelope) error {
  520. switch msg := envelope.Message.(type) {
  521. case *ssproto.ChunkRequest:
  522. r.Logger.Debug(
  523. "received chunk request",
  524. "height", msg.Height,
  525. "format", msg.Format,
  526. "chunk", msg.Index,
  527. "peer", envelope.From,
  528. )
  529. resp, err := r.conn.LoadSnapshotChunkSync(context.TODO(), abci.RequestLoadSnapshotChunk{
  530. Height: msg.Height,
  531. Format: msg.Format,
  532. Chunk: msg.Index,
  533. })
  534. if err != nil {
  535. r.Logger.Error(
  536. "failed to load chunk",
  537. "height", msg.Height,
  538. "format", msg.Format,
  539. "chunk", msg.Index,
  540. "err", err,
  541. "peer", envelope.From,
  542. )
  543. return nil
  544. }
  545. r.Logger.Debug(
  546. "sending chunk",
  547. "height", msg.Height,
  548. "format", msg.Format,
  549. "chunk", msg.Index,
  550. "peer", envelope.From,
  551. )
  552. r.chunkCh.Out <- p2p.Envelope{
  553. To: envelope.From,
  554. Message: &ssproto.ChunkResponse{
  555. Height: msg.Height,
  556. Format: msg.Format,
  557. Index: msg.Index,
  558. Chunk: resp.Chunk,
  559. Missing: resp.Chunk == nil,
  560. },
  561. }
  562. case *ssproto.ChunkResponse:
  563. r.mtx.RLock()
  564. defer r.mtx.RUnlock()
  565. if r.syncer == nil {
  566. r.Logger.Debug("received unexpected chunk; no state sync in progress", "peer", envelope.From)
  567. return nil
  568. }
  569. r.Logger.Debug(
  570. "received chunk; adding to sync",
  571. "height", msg.Height,
  572. "format", msg.Format,
  573. "chunk", msg.Index,
  574. "peer", envelope.From,
  575. )
  576. _, err := r.syncer.AddChunk(&chunk{
  577. Height: msg.Height,
  578. Format: msg.Format,
  579. Index: msg.Index,
  580. Chunk: msg.Chunk,
  581. Sender: envelope.From,
  582. })
  583. if err != nil {
  584. r.Logger.Error(
  585. "failed to add chunk",
  586. "height", msg.Height,
  587. "format", msg.Format,
  588. "chunk", msg.Index,
  589. "err", err,
  590. "peer", envelope.From,
  591. )
  592. return nil
  593. }
  594. default:
  595. return fmt.Errorf("received unknown message: %T", msg)
  596. }
  597. return nil
  598. }
  599. func (r *Reactor) handleLightBlockMessage(envelope p2p.Envelope) error {
  600. switch msg := envelope.Message.(type) {
  601. case *ssproto.LightBlockRequest:
  602. r.Logger.Info("received light block request", "height", msg.Height)
  603. lb, err := r.fetchLightBlock(msg.Height)
  604. if err != nil {
  605. r.Logger.Error("failed to retrieve light block", "err", err, "height", msg.Height)
  606. return err
  607. }
  608. if lb == nil {
  609. r.blockCh.Out <- p2p.Envelope{
  610. To: envelope.From,
  611. Message: &ssproto.LightBlockResponse{
  612. LightBlock: nil,
  613. },
  614. }
  615. return nil
  616. }
  617. lbproto, err := lb.ToProto()
  618. if err != nil {
  619. r.Logger.Error("marshaling light block to proto", "err", err)
  620. return nil
  621. }
  622. // NOTE: If we don't have the light block we will send a nil light block
  623. // back to the requested node, indicating that we don't have it.
  624. r.blockCh.Out <- p2p.Envelope{
  625. To: envelope.From,
  626. Message: &ssproto.LightBlockResponse{
  627. LightBlock: lbproto,
  628. },
  629. }
  630. case *ssproto.LightBlockResponse:
  631. var height int64
  632. if msg.LightBlock != nil {
  633. height = msg.LightBlock.SignedHeader.Header.Height
  634. }
  635. r.Logger.Info("received light block response", "peer", envelope.From, "height", height)
  636. if err := r.dispatcher.Respond(msg.LightBlock, envelope.From); err != nil {
  637. r.Logger.Error("error processing light block response", "err", err, "height", height)
  638. }
  639. default:
  640. return fmt.Errorf("received unknown message: %T", msg)
  641. }
  642. return nil
  643. }
  644. func (r *Reactor) handleParamsMessage(envelope p2p.Envelope) error {
  645. switch msg := envelope.Message.(type) {
  646. case *ssproto.ParamsRequest:
  647. r.Logger.Debug("received consensus params request", "height", msg.Height)
  648. cp, err := r.stateStore.LoadConsensusParams(int64(msg.Height))
  649. if err != nil {
  650. r.Logger.Error("failed to fetch requested consensus params", "err", err, "height", msg.Height)
  651. return nil
  652. }
  653. cpproto := cp.ToProto()
  654. r.paramsCh.Out <- p2p.Envelope{
  655. To: envelope.From,
  656. Message: &ssproto.ParamsResponse{
  657. Height: msg.Height,
  658. ConsensusParams: cpproto,
  659. },
  660. }
  661. case *ssproto.ParamsResponse:
  662. r.mtx.RLock()
  663. defer r.mtx.RUnlock()
  664. r.Logger.Debug("received consensus params response", "height", msg.Height)
  665. cp := types.ConsensusParamsFromProto(msg.ConsensusParams)
  666. if sp, ok := r.stateProvider.(*stateProviderP2P); ok {
  667. select {
  668. case sp.paramsRecvCh <- cp:
  669. case <-time.After(time.Second):
  670. return errors.New("failed to send consensus params, stateprovider not ready for response")
  671. }
  672. } else {
  673. r.Logger.Debug("received unexpected params response; using RPC state provider", "peer", envelope.From)
  674. }
  675. default:
  676. return fmt.Errorf("received unknown message: %T", msg)
  677. }
  678. return nil
  679. }
  680. // handleMessage handles an Envelope sent from a peer on a specific p2p Channel.
  681. // It will handle errors and any possible panics gracefully. A caller can handle
  682. // any error returned by sending a PeerError on the respective channel.
  683. func (r *Reactor) handleMessage(chID p2p.ChannelID, envelope p2p.Envelope) (err error) {
  684. defer func() {
  685. if e := recover(); e != nil {
  686. err = fmt.Errorf("panic in processing message: %v", e)
  687. r.Logger.Error(
  688. "recovering from processing message panic",
  689. "err", err,
  690. "stack", string(debug.Stack()),
  691. )
  692. }
  693. }()
  694. r.Logger.Debug("received message", "message", reflect.TypeOf(envelope.Message), "peer", envelope.From)
  695. switch chID {
  696. case SnapshotChannel:
  697. err = r.handleSnapshotMessage(envelope)
  698. case ChunkChannel:
  699. err = r.handleChunkMessage(envelope)
  700. case LightBlockChannel:
  701. err = r.handleLightBlockMessage(envelope)
  702. case ParamsChannel:
  703. err = r.handleParamsMessage(envelope)
  704. default:
  705. err = fmt.Errorf("unknown channel ID (%d) for envelope (%v)", chID, envelope)
  706. }
  707. return err
  708. }
  709. // processCh routes state sync messages to their respective handlers. Any error
  710. // encountered during message execution will result in a PeerError being sent on
  711. // the respective channel. When the reactor is stopped, we will catch the signal
  712. // and close the p2p Channel gracefully.
  713. func (r *Reactor) processCh(ctx context.Context, ch *p2p.Channel, chName string) {
  714. for {
  715. select {
  716. case <-ctx.Done():
  717. return
  718. case envelope := <-ch.In:
  719. if err := r.handleMessage(ch.ID, envelope); err != nil {
  720. r.Logger.Error("failed to process message",
  721. "err", err,
  722. "channel", chName,
  723. "ch_id", ch.ID,
  724. "envelope", envelope)
  725. ch.Error <- p2p.PeerError{
  726. NodeID: envelope.From,
  727. Err: err,
  728. }
  729. }
  730. case <-r.closeCh:
  731. r.Logger.Debug("channel closed", "channel", chName)
  732. return
  733. }
  734. }
  735. }
  736. // processPeerUpdate processes a PeerUpdate, returning an error upon failing to
  737. // handle the PeerUpdate or if a panic is recovered.
  738. func (r *Reactor) processPeerUpdate(peerUpdate p2p.PeerUpdate) {
  739. r.Logger.Info("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
  740. switch peerUpdate.Status {
  741. case p2p.PeerStatusUp:
  742. r.peers.Append(peerUpdate.NodeID)
  743. case p2p.PeerStatusDown:
  744. r.peers.Remove(peerUpdate.NodeID)
  745. }
  746. r.mtx.Lock()
  747. defer r.mtx.Unlock()
  748. if r.syncer == nil {
  749. return
  750. }
  751. switch peerUpdate.Status {
  752. case p2p.PeerStatusUp:
  753. newProvider := NewBlockProvider(peerUpdate.NodeID, r.chainID, r.dispatcher)
  754. r.providers[peerUpdate.NodeID] = newProvider
  755. err := r.syncer.AddPeer(peerUpdate.NodeID)
  756. if err != nil {
  757. r.Logger.Error("error adding peer to syncer", "error", err)
  758. return
  759. }
  760. if sp, ok := r.stateProvider.(*stateProviderP2P); ok {
  761. // we do this in a separate routine to not block whilst waiting for the light client to finish
  762. // whatever call it's currently executing
  763. go sp.addProvider(newProvider)
  764. }
  765. case p2p.PeerStatusDown:
  766. delete(r.providers, peerUpdate.NodeID)
  767. r.syncer.RemovePeer(peerUpdate.NodeID)
  768. }
  769. r.Logger.Info("processed peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status)
  770. }
  771. // processPeerUpdates initiates a blocking process where we listen for and handle
  772. // PeerUpdate messages. When the reactor is stopped, we will catch the signal and
  773. // close the p2p PeerUpdatesCh gracefully.
  774. func (r *Reactor) processPeerUpdates(ctx context.Context) {
  775. defer r.peerUpdates.Close()
  776. for {
  777. select {
  778. case <-ctx.Done():
  779. return
  780. case peerUpdate := <-r.peerUpdates.Updates():
  781. r.processPeerUpdate(peerUpdate)
  782. case <-r.closeCh:
  783. r.Logger.Debug("stopped listening on peer updates channel; closing...")
  784. return
  785. }
  786. }
  787. }
  788. // recentSnapshots fetches the n most recent snapshots from the app
  789. func (r *Reactor) recentSnapshots(n uint32) ([]*snapshot, error) {
  790. resp, err := r.conn.ListSnapshotsSync(context.TODO(), abci.RequestListSnapshots{})
  791. if err != nil {
  792. return nil, err
  793. }
  794. sort.Slice(resp.Snapshots, func(i, j int) bool {
  795. a := resp.Snapshots[i]
  796. b := resp.Snapshots[j]
  797. switch {
  798. case a.Height > b.Height:
  799. return true
  800. case a.Height == b.Height && a.Format > b.Format:
  801. return true
  802. default:
  803. return false
  804. }
  805. })
  806. snapshots := make([]*snapshot, 0, n)
  807. for i, s := range resp.Snapshots {
  808. if i >= recentSnapshots {
  809. break
  810. }
  811. snapshots = append(snapshots, &snapshot{
  812. Height: s.Height,
  813. Format: s.Format,
  814. Chunks: s.Chunks,
  815. Hash: s.Hash,
  816. Metadata: s.Metadata,
  817. })
  818. }
  819. return snapshots, nil
  820. }
  821. // fetchLightBlock works out whether the node has a light block at a particular
  822. // height and if so returns it so it can be gossiped to peers
  823. func (r *Reactor) fetchLightBlock(height uint64) (*types.LightBlock, error) {
  824. h := int64(height)
  825. blockMeta := r.blockStore.LoadBlockMeta(h)
  826. if blockMeta == nil {
  827. return nil, nil
  828. }
  829. commit := r.blockStore.LoadBlockCommit(h)
  830. if commit == nil {
  831. return nil, nil
  832. }
  833. vals, err := r.stateStore.LoadValidators(h)
  834. if err != nil {
  835. return nil, err
  836. }
  837. if vals == nil {
  838. return nil, nil
  839. }
  840. return &types.LightBlock{
  841. SignedHeader: &types.SignedHeader{
  842. Header: &blockMeta.Header,
  843. Commit: commit,
  844. },
  845. ValidatorSet: vals,
  846. }, nil
  847. }
  848. func (r *Reactor) waitForEnoughPeers(ctx context.Context, numPeers int) error {
  849. startAt := time.Now()
  850. t := time.NewTicker(100 * time.Millisecond)
  851. defer t.Stop()
  852. logT := time.NewTicker(time.Minute)
  853. defer logT.Stop()
  854. var iter int
  855. for r.peers.Len() < numPeers {
  856. iter++
  857. select {
  858. case <-ctx.Done():
  859. return fmt.Errorf("operation canceled while waiting for peers after %.2fs [%d/%d]",
  860. time.Since(startAt).Seconds(), r.peers.Len(), numPeers)
  861. case <-r.closeCh:
  862. return fmt.Errorf("shutdown while waiting for peers after %.2fs [%d/%d]",
  863. time.Since(startAt).Seconds(), r.peers.Len(), numPeers)
  864. case <-t.C:
  865. continue
  866. case <-logT.C:
  867. r.Logger.Info("waiting for sufficient peers to start statesync",
  868. "duration", time.Since(startAt).String(),
  869. "target", numPeers,
  870. "peers", r.peers.Len(),
  871. "iters", iter,
  872. )
  873. continue
  874. }
  875. }
  876. return nil
  877. }
  878. func (r *Reactor) initStateProvider(ctx context.Context, chainID string, initialHeight int64) error {
  879. var err error
  880. to := light.TrustOptions{
  881. Period: r.cfg.TrustPeriod,
  882. Height: r.cfg.TrustHeight,
  883. Hash: r.cfg.TrustHashBytes(),
  884. }
  885. spLogger := r.Logger.With("module", "stateprovider")
  886. spLogger.Info("initializing state provider", "trustPeriod", to.Period,
  887. "trustHeight", to.Height, "useP2P", r.cfg.UseP2P)
  888. if r.cfg.UseP2P {
  889. if err := r.waitForEnoughPeers(ctx, 2); err != nil {
  890. return err
  891. }
  892. peers := r.peers.All()
  893. providers := make([]provider.Provider, len(peers))
  894. for idx, p := range peers {
  895. providers[idx] = NewBlockProvider(p, chainID, r.dispatcher)
  896. }
  897. r.stateProvider, err = NewP2PStateProvider(ctx, chainID, initialHeight, providers, to, r.paramsCh.Out, spLogger)
  898. if err != nil {
  899. return fmt.Errorf("failed to initialize P2P state provider: %w", err)
  900. }
  901. } else {
  902. r.stateProvider, err = NewRPCStateProvider(ctx, chainID, initialHeight, r.cfg.RPCServers, to, spLogger)
  903. if err != nil {
  904. return fmt.Errorf("failed to initialize RPC state provider: %w", err)
  905. }
  906. }
  907. return nil
  908. }
  909. func (r *Reactor) TotalSnapshots() int64 {
  910. r.mtx.RLock()
  911. defer r.mtx.RUnlock()
  912. if r.syncer != nil && r.syncer.snapshots != nil {
  913. return int64(len(r.syncer.snapshots.snapshots))
  914. }
  915. return 0
  916. }
  917. func (r *Reactor) ChunkProcessAvgTime() time.Duration {
  918. r.mtx.RLock()
  919. defer r.mtx.RUnlock()
  920. if r.syncer != nil {
  921. return time.Duration(r.syncer.avgChunkTime)
  922. }
  923. return time.Duration(0)
  924. }
  925. func (r *Reactor) SnapshotHeight() int64 {
  926. r.mtx.RLock()
  927. defer r.mtx.RUnlock()
  928. if r.syncer != nil {
  929. return r.syncer.lastSyncedSnapshotHeight
  930. }
  931. return 0
  932. }
  933. func (r *Reactor) SnapshotChunksCount() int64 {
  934. r.mtx.RLock()
  935. defer r.mtx.RUnlock()
  936. if r.syncer != nil && r.syncer.chunks != nil {
  937. return int64(r.syncer.chunks.numChunksReturned())
  938. }
  939. return 0
  940. }
  941. func (r *Reactor) SnapshotChunksTotal() int64 {
  942. r.mtx.RLock()
  943. defer r.mtx.RUnlock()
  944. if r.syncer != nil && r.syncer.processingSnapshot != nil {
  945. return int64(r.syncer.processingSnapshot.Chunks)
  946. }
  947. return 0
  948. }
  949. func (r *Reactor) BackFilledBlocks() int64 {
  950. r.mtx.RLock()
  951. defer r.mtx.RUnlock()
  952. return r.backfilledBlocks
  953. }
  954. func (r *Reactor) BackFillBlocksTotal() int64 {
  955. r.mtx.RLock()
  956. defer r.mtx.RUnlock()
  957. return r.backfillBlockTotal
  958. }