From e67b1e26bb00ecedc17c80d1492248a9c0eb3249 Mon Sep 17 00:00:00 2001 From: noot <36753753+noot@users.noreply.github.com> Date: Tue, 15 Jun 2021 18:20:38 -0400 Subject: [PATCH] fix(lib/babe): fix timing for transition between epochs (#1636) --- go.mod | 1 - lib/babe/babe.go | 210 +++++++++++++++++++--------------- lib/babe/babe_test.go | 31 +++++ lib/babe/build.go | 2 +- lib/babe/epoch.go | 7 +- lib/babe/epoch_test.go | 25 ++-- lib/babe/types.go | 9 ++ lib/common/uint128.go | 5 + lib/keystore/mock_keyring.go | 157 +++++++++++++++++++++++++ lib/keystore/mock_keystore.go | 126 ++++++++++++++++++++ 10 files changed, 468 insertions(+), 105 deletions(-) create mode 100644 lib/keystore/mock_keyring.go create mode 100644 lib/keystore/mock_keystore.go diff --git a/go.mod b/go.mod index 84bfa0a2dd..c27a74dda7 100644 --- a/go.mod +++ b/go.mod @@ -38,7 +38,6 @@ require ( github.com/libp2p/go-libp2p-core v0.7.0 github.com/libp2p/go-libp2p-discovery v0.5.0 github.com/libp2p/go-libp2p-kad-dht v0.11.1 - github.com/libp2p/go-libp2p-kbucket v0.4.7 github.com/libp2p/go-libp2p-peerstore v0.2.6 github.com/libp2p/go-libp2p-secio v0.2.2 github.com/libp2p/go-sockaddr v0.1.0 // indirect diff --git a/lib/babe/babe.go b/lib/babe/babe.go index ffef043ae2..6618d0ae90 100644 --- a/lib/babe/babe.go +++ b/lib/babe/babe.go @@ -38,7 +38,6 @@ var logger log.Logger type Service struct { ctx context.Context cancel context.CancelFunc - paused bool authority bool dev bool @@ -123,7 +122,7 @@ func NewService(cfg *ServiceConfig) (*Service, error) { rt: cfg.Runtime, transactionState: cfg.TransactionState, slotToProof: make(map[uint64]*VrfOutputAndProof), - blockChan: make(chan types.Block), + blockChan: make(chan types.Block, 16), pause: make(chan struct{}), authority: cfg.Authority, dev: cfg.IsDev, @@ -146,7 +145,7 @@ func NewService(cfg *ServiceConfig) (*Service, error) { "epoch length (slots)", babeService.epochLength, "authorities", Authorities(babeService.epochData.authorities), "authority index", babeService.epochData.authorityIndex, - "threshold", babeService.epochData.threshold.ToLEBytes(), + "threshold", babeService.epochData.threshold, "randomness", babeService.epochData.randomness, ) return babeService, nil @@ -226,39 +225,49 @@ func (b *Service) EpochLength() uint64 { // Pause pauses the service ie. halts block production func (b *Service) Pause() error { - if b.paused { - return errors.New("service already paused") - } - b.Lock() defer b.Unlock() - b.pause <- struct{}{} - b.paused = true + if b.IsPaused() { + return nil + } + + close(b.pause) return nil } // Resume resumes the service ie. resumes block production func (b *Service) Resume() error { - if !b.paused { + b.Lock() + defer b.Unlock() + + if !b.IsPaused() { return nil } + b.pause = make(chan struct{}) + epoch, err := b.epochState.GetCurrentEpoch() if err != nil { logger.Error("failed to get current epoch", "error", err) return err } - b.Lock() - defer b.Unlock() - - b.paused = false go b.initiate(epoch) logger.Info("service resumed", "epoch", epoch) return nil } +// IsPaused returns if the service is paused or not (ie. producing blocks) +func (b *Service) IsPaused() bool { + select { + case <-b.pause: + return true + default: + return false + } +} + // Stop stops the service. If stop is called, it cannot be resumed. func (b *Service) Stop() error { b.Lock() @@ -301,13 +310,6 @@ func (b *Service) IsStopped() bool { return b.ctx.Err() != nil } -// IsPaused returns if the service is paused or not (ie. producing blocks) -func (b *Service) IsPaused() bool { - b.RLock() - defer b.RUnlock() - return b.paused -} - func (b *Service) safeSend(msg types.Block) error { b.Lock() defer b.Unlock() @@ -351,93 +353,115 @@ func (b *Service) initiate(epoch uint64) { return } - b.invokeBlockAuthoring(epoch) + err := b.invokeBlockAuthoring(epoch) + if err != nil { + logger.Crit("block authoring error", "error", err) + } } -func (b *Service) invokeBlockAuthoring(epoch uint64) { - // calculate current slot - startSlot := getCurrentSlot(b.slotDuration) +func (b *Service) invokeBlockAuthoring(epoch uint64) error { + for { + // get start slot for current epoch + epochStart, err := b.epochState.GetStartSlotForEpoch(epoch) + if err != nil { + logger.Error("failed to get start slot for current epoch", "epoch", epoch, "error", err) + return err + } - head, err := b.blockState.BestBlockHeader() - if err != nil { - logger.Error("failed to get best block header", "error", err) - return - } + head, err := b.blockState.BestBlockHeader() + if err != nil { + logger.Error("failed to get best block header", "error", err) + return err + } - // if we're at genesis, set the first slot number for the network - if head.Number.Cmp(big.NewInt(0)) == 0 { - err = b.epochState.SetFirstSlot(startSlot) + // if we're at genesis, set the first slot number for the network + if head.Number.Cmp(big.NewInt(0)) == 0 { + epochStart = getCurrentSlot(b.slotDuration) + err = b.epochState.SetFirstSlot(epochStart) + if err != nil { + logger.Error("failed to set first slot number", "error", err) + return err + } + } + + logger.Info("initiating epoch", "number", epoch, "first slot of epoch", epochStart) + err = b.initiateEpoch(epoch) if err != nil { - logger.Error("failed to set first slot number", "error", err) - return + logger.Error("failed to initiate epoch", "epoch", epoch, "error", err) + return err } - } - logger.Info("initiating epoch", "number", epoch, "start slot", startSlot+b.epochLength) - err = b.initiateEpoch(epoch) - if err != nil { - logger.Error("failed to initiate epoch", "epoch", epoch, "error", err) - return - } + epochStartTime := getSlotStartTime(epochStart, b.slotDuration) + logger.Debug("checking if epoch started", "epoch start", epochStartTime, "now", time.Now()) + + // check if it's time to start the epoch yet. if not, wait until it is + if time.Since(epochStartTime) < 0 { + logger.Debug("waiting for epoch to start") + select { + case <-time.After(time.Until(epochStartTime)): + case <-b.ctx.Done(): + return nil + case <-b.pause: + return nil + } + } - // get start slot for current epoch - epochStart, err := b.epochState.GetStartSlotForEpoch(0) - if err != nil { - logger.Error("failed to get start slot for current epoch", "epoch", epoch, "error", err) - return - } + // calculate current slot + startSlot := getCurrentSlot(b.slotDuration) + intoEpoch := startSlot - epochStart - intoEpoch := startSlot - epochStart - logger.Info("current epoch", "epoch", epoch, "slots into epoch", intoEpoch) + // if the calculated amount of slots "into the epoch" is greater than the epoch length, + // we've been offline for more than an epoch, and need to sync. pause BABE for now, syncer will + // resume it when ready + if b.epochLength <= intoEpoch && !b.dev { + logger.Debug("pausing BABE, need to sync", "slots into epoch", intoEpoch, "startSlot", startSlot, "epochStart", epochStart) + return b.Pause() + } - // if the calculated amount of slots "into the epoch" is greater than the epoch length, - // we've been offline for more than an epoch, and need to sync. pause BABE for now, syncer will - // resume it when ready - if b.epochLength <= intoEpoch && !b.dev { - b.paused = true - return - } + if b.dev { + intoEpoch = intoEpoch % b.epochLength + } - if b.dev { - intoEpoch = intoEpoch % b.epochLength - } + logger.Info("current epoch", "epoch", epoch, "slots into epoch", intoEpoch) - slotDone := make([]<-chan time.Time, b.epochLength-intoEpoch) - for i := 0; i < int(b.epochLength-intoEpoch); i++ { - slotDone[i] = time.After(b.getSlotDuration() * time.Duration(i)) - } + slotDone := make([]<-chan time.Time, b.epochLength-intoEpoch) + for i := 0; i < int(b.epochLength-intoEpoch); i++ { + slotDone[i] = time.After(b.getSlotDuration() * time.Duration(i)) + } - for i := 0; i < int(b.epochLength-intoEpoch); i++ { - select { - case <-b.ctx.Done(): - return - case <-b.pause: - return - case <-slotDone[i]: - if !b.authority { - continue + for i := 0; i < int(b.epochLength-intoEpoch); i++ { + select { + case <-b.ctx.Done(): + return nil + case <-b.pause: + return nil + case <-slotDone[i]: + if !b.authority { + continue + } + + slotNum := startSlot + uint64(i) + err = b.handleSlot(slotNum) + if err == ErrNotAuthorized { + logger.Debug("not authorized to produce a block in this slot", "slot", slotNum, "slots into epoch", i) + continue + } else if err != nil { + logger.Warn("failed to handle slot", "slot", slotNum, "error", err) + continue + } } + } - slotNum := startSlot + uint64(i) - err = b.handleSlot(slotNum) - if err == ErrNotAuthorized { - logger.Debug("not authorized to produce a block in this slot", "slot", slotNum) - continue - } else if err != nil { - logger.Warn("failed to handle slot", "slot", slotNum, "error", err) - continue - } + // setup next epoch, re-invoke block authoring + next, err := b.incrementEpoch() + if err != nil { + logger.Error("failed to increment epoch", "error", err) + return err } - } - // setup next epoch, re-invoke block authoring - next, err := b.incrementEpoch() - if err != nil { - logger.Error("failed to increment epoch", "error", err) - return + logger.Info("epoch complete!", "completed epoch", epoch, "upcoming epoch", next) + epoch = next } - - b.invokeBlockAuthoring(next) } func (b *Service) handleSlot(slotNum uint64) error { @@ -466,8 +490,6 @@ func (b *Service) handleSlot(slotNum uint64) error { number: slotNum, } - logger.Debug("going to build block", "parent", parent) - // set runtime trie before building block // if block building is successful, store the resulting trie in the storage state ts, err := b.storageState.TrieState(&parent.StateRoot) @@ -509,3 +531,7 @@ func (b *Service) handleSlot(slotNum uint64) error { func getCurrentSlot(slotDuration time.Duration) uint64 { return uint64(time.Now().UnixNano()) / uint64(slotDuration.Nanoseconds()) } + +func getSlotStartTime(slot uint64, slotDuration time.Duration) time.Time { + return time.Unix(0, int64(slot)*slotDuration.Nanoseconds()) +} diff --git a/lib/babe/babe_test.go b/lib/babe/babe_test.go index a1a7058f3e..646a4b3633 100644 --- a/lib/babe/babe_test.go +++ b/lib/babe/babe_test.go @@ -136,6 +136,7 @@ func createTestService(t *testing.T, cfg *ServiceConfig) *Service { cfg.Runtime = rt } + cfg.LogLvl = defaultTestLogLvl babeService, err := NewService(cfg) require.NoError(t, err) return babeService @@ -252,3 +253,33 @@ func TestStartAndStop(t *testing.T) { err = bs.Stop() require.NoError(t, err) } + +func TestService_PauseAndResume(t *testing.T) { + bs := createTestService(t, &ServiceConfig{ + LogLvl: log.LvlCrit, + }) + err := bs.Start() + require.NoError(t, err) + time.Sleep(time.Second) + + go func() { + _ = bs.Pause() + }() + + go func() { + _ = bs.Pause() + }() + + go func() { + err := bs.Resume() //nolint + require.NoError(t, err) + }() + + go func() { + err := bs.Resume() //nolint + require.NoError(t, err) + }() + + err = bs.Stop() + require.NoError(t, err) +} diff --git a/lib/babe/build.go b/lib/babe/build.go index 6fb671887a..8b756625d7 100644 --- a/lib/babe/build.go +++ b/lib/babe/build.go @@ -322,7 +322,7 @@ func (b *BlockBuilder) addToQueue(txs []*transaction.ValidTransaction) { } func hasSlotEnded(slot Slot) bool { - slotEnd := slot.start.Add(slot.duration) + slotEnd := slot.start.Add(slot.duration * 2 / 3) // reserve last 1/3 of slot for block finalisation return time.Since(slotEnd) >= 0 } diff --git a/lib/babe/epoch.go b/lib/babe/epoch.go index 369c5f14b5..5589271a38 100644 --- a/lib/babe/epoch.go +++ b/lib/babe/epoch.go @@ -117,10 +117,15 @@ func (b *Service) initiateEpoch(epoch uint64) error { delete(b.slotToProof, i-b.epochLength) // clear data from previous epoch } - b.slotToProof[i], err = b.runLottery(i, epoch) + proof, err := b.runLottery(i, epoch) if err != nil { return fmt.Errorf("error running slot lottery at slot %d: error %s", i, err) } + + if proof != nil { + b.slotToProof[i] = proof + logger.Trace("claimed slot!", "slot", startSlot, "slots into epoch", i-startSlot) + } } return nil diff --git a/lib/babe/epoch_test.go b/lib/babe/epoch_test.go index 20fb1509c9..880aea8b1f 100644 --- a/lib/babe/epoch_test.go +++ b/lib/babe/epoch_test.go @@ -29,7 +29,7 @@ import ( func TestInitiateEpoch_Epoch0(t *testing.T) { bs := createTestService(t, nil) - bs.epochLength = 5 + bs.epochLength = 10 startSlot := uint64(1000) err := bs.epochState.SetFirstSlot(startSlot) @@ -37,21 +37,27 @@ func TestInitiateEpoch_Epoch0(t *testing.T) { err = bs.initiateEpoch(0) require.NoError(t, err) + count := 0 for i := startSlot; i < startSlot+bs.epochLength; i++ { _, has := bs.slotToProof[i] - require.True(t, has) + if has { + count++ + } } + require.GreaterOrEqual(t, count, 1) } -func TestInitiateEpoch(t *testing.T) { +func TestInitiateEpoch_Epoch1(t *testing.T) { bs := createTestService(t, nil) - bs.epochLength = 5 + bs.epochLength = 10 + + err := bs.initiateEpoch(0) + require.NoError(t, err) state.AddBlocksToState(t, bs.blockState.(*state.BlockState), 1) // epoch 1, check that genesis EpochData and ConfigData was properly set - threshold, err := CalculateThreshold(genesisBABEConfig.C1, genesisBABEConfig.C2, 1) - require.NoError(t, err) + threshold := bs.epochData.threshold auth := &types.Authority{ Key: bs.keypair.Public().(*sr25519.PublicKey), @@ -67,7 +73,7 @@ func TestInitiateEpoch(t *testing.T) { threshold: threshold, } require.Equal(t, expected, bs.epochData) - require.Equal(t, int(bs.epochLength), len(bs.slotToProof)) + require.GreaterOrEqual(t, len(bs.slotToProof), 1) // for epoch 2, set EpochData but not ConfigData edata := &types.EpochData{ @@ -89,7 +95,7 @@ func TestInitiateEpoch(t *testing.T) { require.Equal(t, expected.randomness, bs.epochData.randomness) require.Equal(t, expected.authorityIndex, bs.epochData.authorityIndex) require.Equal(t, expected.threshold, bs.epochData.threshold) - require.Equal(t, int(bs.epochLength*2), len(bs.slotToProof)) + require.GreaterOrEqual(t, len(bs.slotToProof), 1) for i, auth := range bs.epochData.authorities { expAuth, err := expected.authorities[i].Encode() //nolint @@ -130,8 +136,7 @@ func TestInitiateEpoch(t *testing.T) { require.Equal(t, expected, bs.epochData) time.Sleep(time.Second) - // assert slot lottery was run for epochs 0, 1 and 2, 3 - require.Equal(t, int(bs.epochLength*3), len(bs.slotToProof)) + require.GreaterOrEqual(t, len(bs.slotToProof), 1) } func TestIncrementEpoch(t *testing.T) { diff --git a/lib/babe/types.go b/lib/babe/types.go index 05a608cefa..077f4fd079 100644 --- a/lib/babe/types.go +++ b/lib/babe/types.go @@ -70,3 +70,12 @@ type epochData struct { authorities []*types.Authority threshold *common.Uint128 } + +func (ed *epochData) String() string { + return fmt.Sprintf("randomness=%x authorityIndex=%d authorities=%v threshold=%s", + ed.randomness, + ed.authorityIndex, + ed.authorities, + ed.threshold, + ) +} diff --git a/lib/common/uint128.go b/lib/common/uint128.go index 60aca79a21..047c60ee33 100644 --- a/lib/common/uint128.go +++ b/lib/common/uint128.go @@ -17,6 +17,7 @@ package common import ( "encoding/binary" + "fmt" "math/big" ) @@ -66,6 +67,10 @@ func Uint128FromLEBytes(in []byte) *Uint128 { } } +func (u *Uint128) String() string { + return fmt.Sprintf("%d", big.NewInt(0).SetBytes(u.ToBEBytes())) +} + // ToLEBytes returns the Uint128 as a little endian byte slice func (u *Uint128) ToLEBytes() []byte { buf := make([]byte, 16) diff --git a/lib/keystore/mock_keyring.go b/lib/keystore/mock_keyring.go new file mode 100644 index 0000000000..1165d812f7 --- /dev/null +++ b/lib/keystore/mock_keyring.go @@ -0,0 +1,157 @@ +// Code generated by mockery v2.8.0. DO NOT EDIT. + +package keystore + +import ( + crypto "github.com/ChainSafe/gossamer/lib/crypto" + mock "github.com/stretchr/testify/mock" +) + +// MockKeyring is an autogenerated mock type for the Keyring type +type MockKeyring struct { + mock.Mock +} + +// Alice provides a mock function with given fields: +func (_m *MockKeyring) Alice() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Bob provides a mock function with given fields: +func (_m *MockKeyring) Bob() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Charlie provides a mock function with given fields: +func (_m *MockKeyring) Charlie() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Dave provides a mock function with given fields: +func (_m *MockKeyring) Dave() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Eve provides a mock function with given fields: +func (_m *MockKeyring) Eve() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Ferdie provides a mock function with given fields: +func (_m *MockKeyring) Ferdie() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// George provides a mock function with given fields: +func (_m *MockKeyring) George() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Heather provides a mock function with given fields: +func (_m *MockKeyring) Heather() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Ian provides a mock function with given fields: +func (_m *MockKeyring) Ian() crypto.Keypair { + ret := _m.Called() + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func() crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} diff --git a/lib/keystore/mock_keystore.go b/lib/keystore/mock_keystore.go new file mode 100644 index 0000000000..c741132f2a --- /dev/null +++ b/lib/keystore/mock_keystore.go @@ -0,0 +1,126 @@ +// Code generated by mockery v2.8.0. DO NOT EDIT. + +package keystore + +import ( + common "github.com/ChainSafe/gossamer/lib/common" + crypto "github.com/ChainSafe/gossamer/lib/crypto" + + mock "github.com/stretchr/testify/mock" +) + +// MockKeystore is an autogenerated mock type for the Keystore type +type MockKeystore struct { + mock.Mock +} + +// GetKeypair provides a mock function with given fields: pub +func (_m *MockKeystore) GetKeypair(pub crypto.PublicKey) crypto.Keypair { + ret := _m.Called(pub) + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func(crypto.PublicKey) crypto.Keypair); ok { + r0 = rf(pub) + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// GetKeypairFromAddress provides a mock function with given fields: pub +func (_m *MockKeystore) GetKeypairFromAddress(pub common.Address) crypto.Keypair { + ret := _m.Called(pub) + + var r0 crypto.Keypair + if rf, ok := ret.Get(0).(func(common.Address) crypto.Keypair); ok { + r0 = rf(pub) + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).(crypto.Keypair) + } + } + + return r0 +} + +// Insert provides a mock function with given fields: kp +func (_m *MockKeystore) Insert(kp crypto.Keypair) { + _m.Called(kp) +} + +// Keypairs provides a mock function with given fields: +func (_m *MockKeystore) Keypairs() []crypto.Keypair { + ret := _m.Called() + + var r0 []crypto.Keypair + if rf, ok := ret.Get(0).(func() []crypto.Keypair); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).([]crypto.Keypair) + } + } + + return r0 +} + +// Name provides a mock function with given fields: +func (_m *MockKeystore) Name() Name { + ret := _m.Called() + + var r0 Name + if rf, ok := ret.Get(0).(func() Name); ok { + r0 = rf() + } else { + r0 = ret.Get(0).(Name) + } + + return r0 +} + +// PublicKeys provides a mock function with given fields: +func (_m *MockKeystore) PublicKeys() []crypto.PublicKey { + ret := _m.Called() + + var r0 []crypto.PublicKey + if rf, ok := ret.Get(0).(func() []crypto.PublicKey); ok { + r0 = rf() + } else { + if ret.Get(0) != nil { + r0 = ret.Get(0).([]crypto.PublicKey) + } + } + + return r0 +} + +// Size provides a mock function with given fields: +func (_m *MockKeystore) Size() int { + ret := _m.Called() + + var r0 int + if rf, ok := ret.Get(0).(func() int); ok { + r0 = rf() + } else { + r0 = ret.Get(0).(int) + } + + return r0 +} + +// Type provides a mock function with given fields: +func (_m *MockKeystore) Type() string { + ret := _m.Called() + + var r0 string + if rf, ok := ret.Get(0).(func() string); ok { + r0 = rf() + } else { + r0 = ret.Get(0).(string) + } + + return r0 +}