From a33784c4346f7072aaba469c051893c3bfb8ecba Mon Sep 17 00:00:00 2001 From: whyrusleeping Date: Wed, 26 Aug 2020 14:48:53 -0700 Subject: [PATCH 1/2] print block 'age' when validating blocks during sync --- chain/sync.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/chain/sync.go b/chain/sync.go index eae5dfcff..0e5f1a126 100644 --- a/chain/sync.go +++ b/chain/sync.go @@ -655,7 +655,7 @@ func (syncer *Syncer) ValidateBlock(ctx context.Context, b *types.FullBlock) (er validationStart := build.Clock.Now() defer func() { stats.Record(ctx, metrics.BlockValidationDurationMilliseconds.M(metrics.SinceInMilliseconds(validationStart))) - log.Infow("block validation", "took", time.Since(validationStart), "height", b.Header.Height) + log.Infow("block validation", "took", time.Since(validationStart), "height", b.Header.Height, "age", time.Since(time.Unix(int64(b.Header.Timestamp), 0))) }() ctx, span := trace.StartSpan(ctx, "validateBlock") From 36ff37ba47957d74e4824e29f9eb2114ff023660 Mon Sep 17 00:00:00 2001 From: whyrusleeping Date: Wed, 26 Aug 2020 17:51:16 -0700 Subject: [PATCH 2/2] Wait until blocks show up full nodes 'head' before claiming block has been mined --- api/test/blockminer.go | 2 +- api/test/deals.go | 3 ++- api/test/mining.go | 16 +++++++--------- api/test/util.go | 25 ++++++++++++++++++++++--- api/test/window_post.go | 2 +- go.sum | 6 ++++++ miner/miner.go | 18 +++++++++++------- miner/testminer.go | 6 +++--- node/test/builder.go | 9 +++++---- 9 files changed, 58 insertions(+), 29 deletions(-) diff --git a/api/test/blockminer.go b/api/test/blockminer.go index 3f4c2b003..c6433efea 100644 --- a/api/test/blockminer.go +++ b/api/test/blockminer.go @@ -41,7 +41,7 @@ func (bm *BlockMiner) MineBlocks() { nulls := atomic.SwapInt64(&bm.nulls, 0) if err := bm.miner.MineOne(bm.ctx, miner.MineReq{ InjectNulls: abi.ChainEpoch(nulls), - Done: func(bool, error) {}, + Done: func(bool, abi.ChainEpoch, error) {}, }); err != nil { bm.t.Error(err) } diff --git a/api/test/deals.go b/api/test/deals.go index fc469da15..00786e785 100644 --- a/api/test/deals.go +++ b/api/test/deals.go @@ -24,6 +24,7 @@ import ( "github.com/filecoin-project/lotus/build" sealing "github.com/filecoin-project/lotus/extern/storage-sealing" "github.com/filecoin-project/lotus/miner" + "github.com/filecoin-project/specs-actors/actors/abi" dag "github.com/ipfs/go-merkledag" dstest "github.com/ipfs/go-merkledag/test" unixfile "github.com/ipfs/go-unixfs/file" @@ -35,7 +36,7 @@ import ( var MineNext = miner.MineReq{ InjectNulls: 0, - Done: func(bool, error) {}, + Done: func(bool, abi.ChainEpoch, error) {}, } func init() { diff --git a/api/test/mining.go b/api/test/mining.go index 835ab3e79..f912ff305 100644 --- a/api/test/mining.go +++ b/api/test/mining.go @@ -31,22 +31,20 @@ func (ts *testSuite) testMining(t *testing.T) { newHeads, err := api.ChainNotify(ctx) require.NoError(t, err) initHead := (<-newHeads)[0] - if initHead.Val.Height() != 2 { - <-newHeads - } + baseHeight := initHead.Val.Height() h1, err := api.ChainHead(ctx) require.NoError(t, err) - require.Equal(t, abi.ChainEpoch(2), h1.Height()) + require.Equal(t, int64(h1.Height()), int64(baseHeight)) - MineUntilBlock(ctx, t, sn[0], nil) + MineUntilBlock(ctx, t, apis[0], sn[0], nil) require.NoError(t, err) <-newHeads h2, err := api.ChainHead(ctx) require.NoError(t, err) - require.Equal(t, abi.ChainEpoch(3), h2.Height()) + require.Greater(t, int64(h2.Height()), int64(h1.Height())) } func (ts *testSuite) testMiningReal(t *testing.T) { @@ -70,7 +68,7 @@ func (ts *testSuite) testMiningReal(t *testing.T) { require.NoError(t, err) require.Equal(t, abi.ChainEpoch(2), h1.Height()) - MineUntilBlock(ctx, t, sn[0], nil) + MineUntilBlock(ctx, t, apis[0], sn[0], nil) require.NoError(t, err) <-newHeads @@ -79,7 +77,7 @@ func (ts *testSuite) testMiningReal(t *testing.T) { require.NoError(t, err) require.Equal(t, abi.ChainEpoch(3), h2.Height()) - MineUntilBlock(ctx, t, sn[0], nil) + MineUntilBlock(ctx, t, apis[0], sn[0], nil) require.NoError(t, err) <-newHeads @@ -144,7 +142,7 @@ func TestDealMining(t *testing.T, b APIBuilder, blocktime time.Duration, carExpo complChan := minedTwo for atomic.LoadInt32(&mine) != 0 { wait := make(chan int) - mdone := func(mined bool, err error) { + mdone := func(mined bool, _ abi.ChainEpoch, err error) { n := 0 if mined { n = 1 diff --git a/api/test/util.go b/api/test/util.go index 88e0e0fe6..57a6fcae3 100644 --- a/api/test/util.go +++ b/api/test/util.go @@ -3,6 +3,7 @@ package test import ( "context" "testing" + "time" "github.com/filecoin-project/specs-actors/actors/abi" @@ -36,15 +37,17 @@ func SendFunds(ctx context.Context, t *testing.T, sender TestNode, addr address. } } -func MineUntilBlock(ctx context.Context, t *testing.T, sn TestStorageNode, cb func()) { +func MineUntilBlock(ctx context.Context, t *testing.T, fn TestNode, sn TestStorageNode, cb func(abi.ChainEpoch)) { for i := 0; i < 1000; i++ { var success bool var err error + var epoch abi.ChainEpoch wait := make(chan struct{}) mineErr := sn.MineOne(ctx, miner.MineReq{ - Done: func(win bool, e error) { + Done: func(win bool, ep abi.ChainEpoch, e error) { success = win err = e + epoch = ep wait <- struct{}{} }, }) @@ -56,8 +59,24 @@ func MineUntilBlock(ctx context.Context, t *testing.T, sn TestStorageNode, cb fu t.Fatal(err) } if success { + // Wait until it shows up on the given full nodes ChainHead + nloops := 50 + for i := 0; i < nloops; i++ { + ts, err := fn.ChainHead(ctx) + if err != nil { + t.Fatal(err) + } + if ts.Height() == epoch { + break + } + if i == nloops-1 { + t.Fatal("block never managed to sync to node") + } + time.Sleep(time.Millisecond * 10) + } + if cb != nil { - cb() + cb(epoch) } return } diff --git a/api/test/window_post.go b/api/test/window_post.go index 2171324fc..c5c8ec071 100644 --- a/api/test/window_post.go +++ b/api/test/window_post.go @@ -53,7 +53,7 @@ func TestPledgeSector(t *testing.T, b APIBuilder, blocktime time.Duration, nSect defer close(done) for mine { build.Clock.Sleep(blocktime) - if err := sn[0].MineOne(ctx, bminer.MineReq{Done: func(bool, error) { + if err := sn[0].MineOne(ctx, bminer.MineReq{Done: func(bool, abi.ChainEpoch, error) { }}); err != nil { t.Error(err) diff --git a/go.sum b/go.sum index 043899f58..8f7f4ca9d 100644 --- a/go.sum +++ b/go.sum @@ -41,6 +41,7 @@ github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03 github.com/BurntSushi/xgb v0.0.0-20160522181843-27f122750802/go.mod h1:IVnqGOEym/WlBOVXweHU+Q+/VP0lqqI8lqeDx9IjBqo= github.com/DataDog/zstd v1.4.1 h1:3oxKN3wbHibqx897utPC2LTQU4J+IHWWJO+glkAkpFM= github.com/DataDog/zstd v1.4.1/go.mod h1:1jcaCB/ufaK+sKp1NBhlGmpz41jOoPQ35bpF36t7BBo= +github.com/GeertJohan/go.incremental v1.0.0 h1:7AH+pY1XUgQE4Y1HcXYaMqAI0m9yrFqo/jt0CW30vsg= github.com/GeertJohan/go.incremental v1.0.0/go.mod h1:6fAjUhbVuX1KcMD3c8TEgVUqmo4seqhv0i0kdATSkM0= github.com/GeertJohan/go.rice v1.0.0 h1:KkI6O9uMaQU3VEKaj01ulavtF7o1fWT7+pk/4voiMLQ= github.com/GeertJohan/go.rice v1.0.0/go.mod h1:eH6gbSOAUv07dQuZVnBmoDP8mgsM1rtixis4Tib9if0= @@ -62,6 +63,7 @@ github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d h1:licZJFw2RwpH github.com/acarl005/stripansi v0.0.0-20180116102854-5a71ef0e047d/go.mod h1:asat636LX7Bqt5lYEZ27JNDcqxfjdBQuJ/MM4CN/Lzo= github.com/aead/siphash v1.0.1/go.mod h1:Nywa3cDsYNNK3gaciGTWPwHt0wlpNV15vwmswBAUSII= github.com/afex/hystrix-go v0.0.0-20180502004556-fa1af6a1f4f5/go.mod h1:SkGFH1ia65gfNATL8TAiHDNxPzPdmEL5uirI2Uyuz6c= +github.com/akavel/rsrc v0.8.0 h1:zjWn7ukO9Kc5Q62DOJCcxGpXC18RawVtYAGdz2aLlfw= github.com/akavel/rsrc v0.8.0/go.mod h1:uLoCtb9J+EyAqh+26kdrTgmzRBFPGOolLWKpdxkKq+c= github.com/alecthomas/template v0.0.0-20160405071501-a0175ee3bccc/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= github.com/alecthomas/template v0.0.0-20190718012654-fb15b899a751/go.mod h1:LOuyumcjzFXgccqObfd/Ljyb9UuFJ6TxHnclSeseNhc= @@ -674,6 +676,7 @@ github.com/jbenet/goprocess v0.1.4 h1:DRGOFReOMqqDNXwW70QkacFW0YN9QnwLV0Vqk+3oU0 github.com/jbenet/goprocess v0.1.4/go.mod h1:5yspPrukOVuOLORacaBi858NqyClJPQxYZlqdZVfqY4= github.com/jellevandenhooff/dkim v0.0.0-20150330215556-f50fe3d243e1/go.mod h1:E0B/fFc00Y+Rasa88328GlI/XbtyysCtTHZS8h7IrBU= github.com/jessevdk/go-flags v0.0.0-20141203071132-1679536dcc89/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI= +github.com/jessevdk/go-flags v1.4.0 h1:4IU2WS7AumrZ/40jfhf4QVDMsQwqA7VEHozFRrGARJA= github.com/jessevdk/go-flags v1.4.0/go.mod h1:4FA24M0QyGHXBuZZK/XkWh8h0e1EYbRYJSGM75WSRxI= github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af/go.mod h1:Nht3zPeWKUH0NzdCt2Blrr5ys8VGpn0CEB0cQHVjt7k= github.com/jmespath/go-jmespath v0.3.0/go.mod h1:9QtRXoHjLGCJ5IBSaohpXITPlowMeeYCZ7fLUTSywik= @@ -1171,6 +1174,7 @@ github.com/neelance/astrewrite v0.0.0-20160511093645-99348263ae86/go.mod h1:kHJE github.com/neelance/sourcemap v0.0.0-20151028013722-8c68805598ab/go.mod h1:Qr6/a/Q4r9LP1IltGz7tA7iOK1WonHEYhu1HRBA7ZiM= github.com/nikkolasg/hexjson v0.0.0-20181101101858-78e39397e00c h1:5bFTChQxSKNwy8ALwOebjekYExl9HTT9urdawqC95tA= github.com/nikkolasg/hexjson v0.0.0-20181101101858-78e39397e00c/go.mod h1:7qN3Y0BvzRUf4LofcoJplQL10lsFDb4PYlePTVwrP28= +github.com/nkovacs/streamquote v0.0.0-20170412213628-49af9bddb229 h1:E2B8qYyeSgv5MXpmzZXRNp8IAQ4vjxIjhpAf5hv/tAg= github.com/nkovacs/streamquote v0.0.0-20170412213628-49af9bddb229/go.mod h1:0aYXnNPJ8l7uZxf45rWW1a/uME32OF0rhiYGNQ2oF2E= github.com/nxadm/tail v1.4.4 h1:DQuhQpB1tVlglWS2hLQ5OV6B5r8aGxSrPc5Qo6uTN78= github.com/nxadm/tail v1.4.4/go.mod h1:kenIhsEOeOJmVchQTgglprH7qJGnHDVpk1VPCcaMI8A= @@ -1387,7 +1391,9 @@ github.com/urfave/cli v1.22.1/go.mod h1:Gos4lmkARVdJ6EkW0WaNv/tZAAMe9V7XWyB60NtX github.com/urfave/cli/v2 v2.0.0/go.mod h1:SE9GqnLQmjVa0iPEY0f1w3ygNIYcIJ0OKPMoW2caLfQ= github.com/urfave/cli/v2 v2.2.0 h1:JTTnM6wKzdA0Jqodd966MVj4vWbbquZykeX1sKbe2C4= github.com/urfave/cli/v2 v2.2.0/go.mod h1:SE9GqnLQmjVa0iPEY0f1w3ygNIYcIJ0OKPMoW2caLfQ= +github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw= github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyCJ6HpOuEn7z0Csc= +github.com/valyala/fasttemplate v1.0.1 h1:tY9CJiPnMXf1ERmG2EyK7gNUd+c6RKGD0IfU8WdUSz8= github.com/valyala/fasttemplate v1.0.1/go.mod h1:UQGH1tvbgY+Nz5t2n7tXsz52dQxojPUpymEIMZ47gx8= github.com/viant/assertly v0.4.8/go.mod h1:aGifi++jvCrUaklKEKT0BU95igDNaqkvz+49uaYMPRU= github.com/viant/toolbox v0.24.0/go.mod h1:OxMCG57V0PXuIP2HNQrtJf2CjqdmbrOx5EkMILuUhzM= diff --git a/miner/miner.go b/miner/miner.go index ed407a0c7..34f1255a9 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -32,7 +32,7 @@ import ( var log = logging.Logger("miner") // returns a callback reporting whether we mined a blocks in this round -type waitFunc func(ctx context.Context, baseTime uint64) (func(bool, error), abi.ChainEpoch, error) +type waitFunc func(ctx context.Context, baseTime uint64) (func(bool, abi.ChainEpoch, error), abi.ChainEpoch, error) func randTimeOffset(width time.Duration) time.Duration { buf := make([]byte, 8) @@ -52,7 +52,7 @@ func NewMiner(api api.FullNode, epp gen.WinningPoStProver, addr address.Address, api: api, epp: epp, address: addr, - waitFunc: func(ctx context.Context, baseTime uint64) (func(bool, error), abi.ChainEpoch, error) { + waitFunc: func(ctx context.Context, baseTime uint64) (func(bool, abi.ChainEpoch, error), abi.ChainEpoch, error) { // Wait around for half the block time in case other parents come in deadline := baseTime + build.PropagationDelaySecs baseT := time.Unix(int64(deadline), 0) @@ -61,7 +61,7 @@ func NewMiner(api api.FullNode, epp gen.WinningPoStProver, addr address.Address, build.Clock.Sleep(build.Clock.Until(baseT)) - return func(bool, error) {}, 0, nil + return func(bool, abi.ChainEpoch, error) {}, 0, nil }, sf: sf, @@ -150,7 +150,7 @@ func (m *Miner) mine(ctx context.Context) { } var base *MiningBase - var onDone func(bool, error) + var onDone func(bool, abi.ChainEpoch, error) var injectNulls abi.ChainEpoch for { @@ -166,7 +166,7 @@ func (m *Miner) mine(ctx context.Context) { break } if base != nil { - onDone(false, nil) + onDone(false, 0, nil) } // TODO: need to change the orchestration here. the problem is that @@ -205,12 +205,16 @@ func (m *Miner) mine(ctx context.Context) { if err != nil { log.Errorf("mining block failed: %+v", err) m.niceSleep(time.Second) - onDone(false, err) + onDone(false, 0, err) continue } lastBase = *base - onDone(b != nil, nil) + var h abi.ChainEpoch + if b != nil { + h = b.Header.Height + } + onDone(b != nil, h, nil) if b != nil { journal.Add("blockMined", map[string]interface{}{ diff --git a/miner/testminer.go b/miner/testminer.go index f5c7243e8..0b1cbb12b 100644 --- a/miner/testminer.go +++ b/miner/testminer.go @@ -15,7 +15,7 @@ import ( type MineReq struct { InjectNulls abi.ChainEpoch - Done func(bool, error) + Done func(bool, abi.ChainEpoch, error) } func NewTestMiner(nextCh <-chan MineReq, addr address.Address) func(api.FullNode, gen.WinningPoStProver) *Miner { @@ -41,8 +41,8 @@ func NewTestMiner(nextCh <-chan MineReq, addr address.Address) func(api.FullNode } } -func chanWaiter(next <-chan MineReq) func(ctx context.Context, _ uint64) (func(bool, error), abi.ChainEpoch, error) { - return func(ctx context.Context, _ uint64) (func(bool, error), abi.ChainEpoch, error) { +func chanWaiter(next <-chan MineReq) func(ctx context.Context, _ uint64) (func(bool, abi.ChainEpoch, error), abi.ChainEpoch, error) { + return func(ctx context.Context, _ uint64) (func(bool, abi.ChainEpoch, error), abi.ChainEpoch, error) { select { case <-ctx.Done(): return nil, 0, ctx.Err() diff --git a/node/test/builder.go b/node/test/builder.go index d2d2128d5..64e20e4f2 100644 --- a/node/test/builder.go +++ b/node/test/builder.go @@ -270,11 +270,12 @@ func Builder(t *testing.T, nFull int, storage []test.StorageMiner) ([]test.TestN var wait sync.Mutex wait.Lock() - test.MineUntilBlock(ctx, t, storers[0], func() { + test.MineUntilBlock(ctx, t, fulls[0], storers[0], func(epoch abi.ChainEpoch) { wait.Unlock() }) + wait.Lock() - test.MineUntilBlock(ctx, t, storers[0], func() { + test.MineUntilBlock(ctx, t, fulls[0], storers[0], func(epoch abi.ChainEpoch) { wait.Unlock() }) wait.Lock() @@ -419,11 +420,11 @@ func MockSbBuilder(t *testing.T, nFull int, storage []test.StorageMiner) ([]test var wait sync.Mutex wait.Lock() - test.MineUntilBlock(ctx, t, storers[0], func() { + test.MineUntilBlock(ctx, t, fulls[0], storers[0], func(abi.ChainEpoch) { wait.Unlock() }) wait.Lock() - test.MineUntilBlock(ctx, t, storers[0], func() { + test.MineUntilBlock(ctx, t, fulls[0], storers[0], func(abi.ChainEpoch) { wait.Unlock() }) wait.Lock()