From 95bd89ff64217a925cdb65f5d0678004433dc508 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Wed, 15 May 2019 12:55:43 +0200 Subject: [PATCH 01/22] swarm: push sync --- api/http/server.go | 41 +- chunk/chunk.go | 12 + pss/pss.go | 2 +- pss/pubsub.go | 55 +++ shed/index.go | 6 +- storage/hasherstore.go | 2 +- storage/localstore/localstore.go | 8 +- storage/localstore/subscription_push.go | 2 +- storage/pushsync/protocol.go | 87 ++++ storage/pushsync/pusher.go | 277 ++++++++++++ storage/pushsync/pusher_test.go | 416 +++++++++++++++++++ storage/pushsync/pushsync_simulation_test.go | 280 +++++++++++++ storage/pushsync/storer.go | 119 ++++++ swarm.go | 12 +- 14 files changed, 1310 insertions(+), 9 deletions(-) create mode 100644 pss/pubsub.go create mode 100644 storage/pushsync/protocol.go create mode 100644 storage/pushsync/pusher.go create mode 100644 storage/pushsync/pusher_test.go create mode 100644 storage/pushsync/pushsync_simulation_test.go create mode 100644 storage/pushsync/storer.go diff --git a/api/http/server.go b/api/http/server.go index 516db8b419..2a7113e3f8 100644 --- a/api/http/server.go +++ b/api/http/server.go @@ -42,9 +42,12 @@ import ( "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/sctx" + "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/storage/feed" "github.com/ethersphere/swarm/storage/pin" + "github.com/opentracing/opentracing-go" + olog "github.com/opentracing/opentracing-go/log" "github.com/rs/cors" ) @@ -349,6 +352,15 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { log.Debug("handle.post.files", "ruid", ruid) postFilesCount.Inc(1) + ctx, sp := spancontext.StartSpan(r.Context(), "handle.post.files") + defer sp.Finish() + + quitChan := make(chan struct{}) + defer close(quitChan) + + // periodically monitor the tag for this upload and log its state to the `handle.post.files` span + go periodicTagTrace(s.api.Tags, sctx.GetTag(ctx), quitChan, sp) + contentType, params, err := mime.ParseMediaType(r.Header.Get("Content-Type")) if err != nil { postFilesFail.Inc(1) @@ -375,7 +387,7 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { } log.Debug("resolved key", "ruid", ruid, "key", addr) } else { - addr, err = s.api.NewManifest(r.Context(), toEncrypt) + addr, err = s.api.NewManifest(ctx, toEncrypt) if err != nil { postFilesFail.Inc(1) respondError(w, r, err.Error(), http.StatusInternalServerError) @@ -383,7 +395,7 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { } log.Debug("new manifest", "ruid", ruid, "key", addr) } - newAddr, err := s.api.UpdateManifest(r.Context(), addr, func(mw *api.ManifestWriter) error { + newAddr, err := s.api.UpdateManifest(ctx, addr, func(mw *api.ManifestWriter) error { switch contentType { case tarContentType: _, err := s.handleTarUpload(r, mw) @@ -1134,3 +1146,28 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { func isDecryptError(err error) bool { return strings.Contains(err.Error(), api.ErrDecrypt.Error()) } + +// periodicTagTrace queries the tag every 2 seconds and logs its state to the span +func periodicTagTrace(tags *chunk.Tags, tagUid uint32, q chan struct{}, sp opentracing.Span) { + f := func() { + tag, err := tags.Get(tagUid) + if err != nil { + log.Error("error while getting tag", "tagUid", tagUid, "err", err) + } + + sp.LogFields(olog.String("tag state", fmt.Sprintf("split=%d stored=%d seen=%d synced=%d", tag.Get(chunk.StateSplit), tag.Get(chunk.StateStored), tag.Get(chunk.StateSeen), tag.Get(chunk.StateSynced)))) + } + + for { + select { + case <-q: + f() + + return + default: + f() + + time.Sleep(2 * time.Second) + } + } +} diff --git a/chunk/chunk.go b/chunk/chunk.go index bcce0eba39..50de9c1c56 100644 --- a/chunk/chunk.go +++ b/chunk/chunk.go @@ -40,12 +40,15 @@ type Chunk interface { Data() []byte PinCounter() uint64 WithPinCounter(p uint64) Chunk + TagID() uint32 + WithTagID(t uint32) Chunk } type chunk struct { addr Address sdata []byte pinCounter uint64 + tagID uint32 } func NewChunk(addr Address, data []byte) Chunk { @@ -60,6 +63,11 @@ func (c *chunk) WithPinCounter(p uint64) Chunk { return c } +func (c *chunk) WithTagID(t uint32) Chunk { + c.tagID = t + return c +} + func (c *chunk) Address() Address { return c.addr } @@ -72,6 +80,10 @@ func (c *chunk) PinCounter() uint64 { return c.pinCounter } +func (c *chunk) TagID() uint32 { + return c.tagID +} + func (self *chunk) String() string { return fmt.Sprintf("Address: %v Chunksize: %v", self.addr.Log(), len(self.sdata)) } diff --git a/pss/pss.go b/pss/pss.go index fe04f56943..0c8d4eb11c 100644 --- a/pss/pss.go +++ b/pss/pss.go @@ -734,7 +734,7 @@ func sendMsg(p *Pss, sp *network.Peer, msg *PssMsg) bool { } } if !isPssEnabled { - log.Error("peer doesn't have matching pss capabilities, skipping", "peer", info.Name, "caps", info.Caps) + log.Warn("peer doesn't have matching pss capabilities, skipping", "peer", info.Name, "caps", info.Caps, "peer", fmt.Sprintf("%x", sp.BzzAddr.Address())) return false } diff --git a/pss/pubsub.go b/pss/pubsub.go new file mode 100644 index 0000000000..03ebf9ee5f --- /dev/null +++ b/pss/pubsub.go @@ -0,0 +1,55 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package pss + +import "github.com/ethereum/go-ethereum/p2p" + +// PubSub implements the pushsync.PubSub interface using pss +type PubSub struct { + pss *Pss +} + +// NewPubSub creates a new PubSub +func NewPubSub(p *Pss) *PubSub { + return &PubSub{ + pss: p, + } +} + +// BaseAddr returns Kademlia base address +func (p *PubSub) BaseAddr() []byte { + return p.pss.Kademlia.BaseAddr() +} + +// Register registers a handler +func (p *PubSub) Register(topic string, prox bool, handler func(msg []byte, p *p2p.Peer) error) func() { + f := func(msg []byte, peer *p2p.Peer, _ bool, _ string) error { + return handler(msg, peer) + } + h := NewHandler(f).WithRaw() + if prox { + h = h.WithProxBin() + } + pt := BytesToTopic([]byte(topic)) + return p.pss.Register(&pt, h) +} + +// Send sends a message using pss SendRaw +func (p *PubSub) Send(to []byte, topic string, msg []byte) error { + pt := BytesToTopic([]byte(topic)) + return p.pss.SendRaw(PssAddress(to), pt, msg) +} diff --git a/shed/index.go b/shed/index.go index 57c53d6caa..849a466396 100644 --- a/shed/index.go +++ b/shed/index.go @@ -42,6 +42,7 @@ type Item struct { StoreTimestamp int64 BinID uint64 PinCounter uint64 // maintains the no of time a chunk is pinned + Tag uint32 } // Merge is a helper method to construct a new @@ -66,6 +67,9 @@ func (i Item) Merge(i2 Item) (new Item) { if i.PinCounter == 0 { i.PinCounter = i2.PinCounter } + if i.Tag == 0 { + i.Tag = i2.Tag + } return i } @@ -97,7 +101,7 @@ type IndexFuncs struct { // NewIndex returns a new Index instance with defined name and // encoding functions. The name must be unique and will be validated // on database schema for a key prefix byte. -func (db *DB) NewIndex(name string, funcs IndexFuncs) (f Index, err error) { +func (db *DB) NewIndex(name string, funcs IndexFuncs) (f Index, err error) { id, err := db.schemaIndexPrefix(name) if err != nil { return f, err diff --git a/storage/hasherstore.go b/storage/hasherstore.go index b2592c61bf..4890219a15 100644 --- a/storage/hasherstore.go +++ b/storage/hasherstore.go @@ -191,7 +191,7 @@ func (h *hasherStore) createHash(chunkData ChunkData) Address { func (h *hasherStore) createChunk(chunkData ChunkData) Chunk { hash := h.createHash(chunkData) - chunk := NewChunk(hash, chunkData) + chunk := NewChunk(hash, chunkData).WithTagID(h.tag.Uid) return chunk } diff --git a/storage/localstore/localstore.go b/storage/localstore/localstore.go index 2953de2a97..3c3a881983 100644 --- a/storage/localstore/localstore.go +++ b/storage/localstore/localstore.go @@ -1,4 +1,4 @@ -// Copyright 2018 The go-ethereum Authors +// Copyright 2019 The go-ethereum Authors // This file is part of the go-ethereum library. // // The go-ethereum library is free software: you can redistribute it and/or modify @@ -306,9 +306,12 @@ func New(path string, baseKey []byte, o *Options) (db *DB, err error) { return e, nil }, EncodeValue: func(fields shed.Item) (value []byte, err error) { - return nil, nil + tag := make([]byte, 4) + binary.BigEndian.PutUint32(tag, fields.Tag) + return tag, nil }, DecodeValue: func(keyItem shed.Item, value []byte) (e shed.Item, err error) { + e.Tag = binary.BigEndian.Uint32(value) return e, nil }, }) @@ -417,6 +420,7 @@ func chunkToItem(ch chunk.Chunk) shed.Item { return shed.Item{ Address: ch.Address(), Data: ch.Data(), + Tag: ch.TagID(), } } diff --git a/storage/localstore/subscription_push.go b/storage/localstore/subscription_push.go index c8dd5cf215..94da228d30 100644 --- a/storage/localstore/subscription_push.go +++ b/storage/localstore/subscription_push.go @@ -75,7 +75,7 @@ func (db *DB) SubscribePush(ctx context.Context) (c <-chan chunk.Chunk, stop fun } select { - case chunks <- chunk.NewChunk(dataItem.Address, dataItem.Data): + case chunks <- chunk.NewChunk(dataItem.Address, dataItem.Data).WithTagID(dataItem.Tag): count++ // set next iteration start item // when its chunk is successfully sent to channel diff --git a/storage/pushsync/protocol.go b/storage/pushsync/protocol.go new file mode 100644 index 0000000000..3285f84833 --- /dev/null +++ b/storage/pushsync/protocol.go @@ -0,0 +1,87 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package pushsync + +import ( + "crypto/rand" + + "github.com/ethereum/go-ethereum/common/hexutil" + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/rlp" +) + +const ( + pssChunkTopic = "PUSHSYNC_CHUNKS" // pss topic for chunks + pssReceiptTopic = "PUSHSYNC_RECEIPTS" // pss topic for statement of custody receipts +) + +// PubSub is a Postal Service interface needed to send/receive chunks and receipts for push syncing +type PubSub interface { + Register(topic string, prox bool, handler func(msg []byte, p *p2p.Peer) error) func() + Send(to []byte, topic string, msg []byte) error + BaseAddr() []byte +} + +// chunkMsg is the message construct to send chunks to their local neighbourhood +type chunkMsg struct { + Addr []byte // chunk address + Data []byte // chunk data + Origin []byte // originator - need this for sending receipt back to origin + Nonce []byte // nonce to make multiple instances of send immune to deduplication cache +} + +// receiptMsg is a statement of custody response to receiving a push-synced chunk +// it is currently a notification only (contains no proof) sent to the originator +// Nonce is there to make multiple responses immune to deduplication cache +type receiptMsg struct { + Addr []byte + Nonce []byte +} + +func decodeChunkMsg(msg []byte) (*chunkMsg, error) { + var chmsg chunkMsg + err := rlp.DecodeBytes(msg, &chmsg) + if err != nil { + return nil, err + } + return &chmsg, nil +} + +func decodeReceiptMsg(msg []byte) (*receiptMsg, error) { + var rmsg receiptMsg + err := rlp.DecodeBytes(msg, &rmsg) + if err != nil { + return nil, err + } + return &rmsg, nil +} + +// newNonce creates a random nonce; +// even without POC it is important otherwise resending a chunk is deduplicated by pss +func newNonce() []byte { + buf := make([]byte, 32) + t := 0 + for t < len(buf) { + n, _ := rand.Read(buf[t:]) + t += n + } + return buf +} + +func label(b []byte) string { + return hexutil.Encode(b[:8]) +} diff --git a/storage/pushsync/pusher.go b/storage/pushsync/pusher.go new file mode 100644 index 0000000000..d544ebaced --- /dev/null +++ b/storage/pushsync/pusher.go @@ -0,0 +1,277 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package pushsync + +import ( + "context" + "time" + + "github.com/ethereum/go-ethereum/metrics" + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/rlp" + "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/log" + "github.com/ethersphere/swarm/storage" +) + +// DB interface implemented by localstore +type DB interface { + // subscribe to chunk to be push synced - iterates from earliest to newest + SubscribePush(context.Context) (<-chan storage.Chunk, func()) + // called to set a chunk as synced - and allow it to be garbage collected + // TODO this should take ... last argument to delete many in one batch + Set(context.Context, chunk.ModeSet, ...storage.Address) error +} + +// Pusher takes care of the push syncing +type Pusher struct { + store DB // localstore DB + tags *chunk.Tags // tags to update counts + quit chan struct{} // channel to signal quitting on all loops + pushed map[string]*pushedItem // cache of items push-synced + receipts chan chunk.Address // channel to receive receipts + ps PubSub // PubSub interface to send chunks and receive receipts +} + +var ( + retryInterval = 2 * time.Second // seconds to wait before retry sync +) + +// pushedItem captures the info needed for the pusher about a chunk during the +// push-sync--receipt roundtrip +type pushedItem struct { + tag *chunk.Tag // tag for the chunk + sentAt time.Time // most recently sent at time + synced bool // set when chunk got synced +} + +// NewPusher contructs a Pusher and starts up the push sync protocol +// takes +// - a DB interface to subscribe to push sync index to allow iterating over recently stored chunks +// - a pubsub interface to send chunks and receive statements of custody +// - tags that hold the several tag +func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { + p := &Pusher{ + store: store, + tags: tags, + quit: make(chan struct{}), + pushed: make(map[string]*pushedItem), + receipts: make(chan chunk.Address), + ps: ps, + } + go p.sync() + return p +} + +// Close closes the pusher +func (p *Pusher) Close() { + close(p.quit) +} + +// sync starts a forever loop that pushes chunks to their neighbourhood +// and receives receipts (statements of custody) for them. +// chunks that are not acknowledged with a receipt are retried +// not earlier than retryInterval after they were last pushed +// the routine also updates counts of states on a tag in order +// to monitor the proportion of saved, sent and synced chunks of +// a file or collection +func (p *Pusher) sync() { + var chunks <-chan chunk.Chunk + var cancel, stop func() + var ctx context.Context + var synced []storage.Address + + // timer + timer := time.NewTimer(0) + defer timer.Stop() + + // register handler for pssReceiptTopic on pss pubsub + deregister := p.ps.Register(pssReceiptTopic, false, func(msg []byte, _ *p2p.Peer) error { + return p.handleReceiptMsg(msg) + }) + defer deregister() + + chunksInBatch := -1 + var batchStartTime time.Time + + for { + select { + + // retry interval timer triggers starting from new + case <-timer.C: + metrics.GetOrRegisterCounter("pusher.subscribe-push", nil).Inc(1) + // TODO: implement some smart retry strategy relying on sent/synced ratio change + // if subscribe was running, stop it + if stop != nil { + stop() + } + for _, addr := range synced { + // set chunk status to synced, insert to db GC index + if err := p.store.Set(context.Background(), chunk.ModeSetSync, addr); err != nil { + log.Warn("error setting chunk to synced", "addr", addr, "err", err) + continue + } + delete(p.pushed, addr.Hex()) + } + // reset synced list + synced = nil + + // we don't want to record the first iteration + if chunksInBatch != -1 { + // this measurement is not a timer, but we want a histogram, so it fits the data structure + metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.hist", nil).Update(time.Duration(chunksInBatch)) + + metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.time", nil).UpdateSince(batchStartTime) + metrics.GetOrRegisterCounter("pusher.subscribe-push.chunks-in-batch", nil).Inc(int64(chunksInBatch)) + } + chunksInBatch = 0 + batchStartTime = time.Now() + + // and start iterating on Push index from the beginning + ctx, cancel = context.WithCancel(context.Background()) + chunks, stop = p.store.SubscribePush(ctx) + // reset timer to go off after retryInterval + timer.Reset(retryInterval) + + // handle incoming chunks + case ch, more := <-chunks: + chunksInBatch++ + // if no more, set to nil and wait for timer + if !more { + chunks = nil + continue + } + + metrics.GetOrRegisterCounter("pusher.send-chunk", nil).Inc(1) + // if no need to sync this chunk then continue + if !p.needToSync(ch) { + continue + } + + metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) + // send the chunk and ignore the error + if err := p.sendChunkMsg(ch); err != nil { + log.Error("error sending chunk", "addr", ch.Address(), "err", err) + } + + // handle incoming receipts + case addr := <-p.receipts: + metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) + log.Debug("synced", "addr", addr) + // ignore if already received receipt + item, found := p.pushed[addr.Hex()] + if !found { + metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) + log.Debug("not wanted or already got... ignore", "addr", addr) + continue + } + if item.synced { + metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) + log.Debug("just synced... ignore", "addr", addr) + continue + } + metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) + // collect synced addresses + synced = append(synced, addr) + // set synced flag + item.synced = true + // increment synced count for the tag if exists + if item.tag != nil { + item.tag.Inc(chunk.StateSynced) + } + + case <-p.quit: + // if there was a subscription, cancel it + if cancel != nil { + cancel() + } + return + } + } +} + +// handleReceiptMsg is a handler for pssReceiptTopic that +// - deserialises receiptMsg and +// - sends the receipted address on a channel +func (p *Pusher) handleReceiptMsg(msg []byte) error { + receipt, err := decodeReceiptMsg(msg) + if err != nil { + return err + } + log.Debug("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) + p.PushReceipt(receipt.Addr) + return nil +} + +// pushReceipt just inserts the address into the channel +// it is also called by the push sync Storer if the originator and storer identical +func (p *Pusher) PushReceipt(addr []byte) { + select { + case p.receipts <- addr: + case <-p.quit: + } +} + +// sendChunkMsg sends chunks to their destination +// using the PubSub interface Send method (e.g., pss neighbourhood addressing) +func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { + cmsg := &chunkMsg{ + Origin: p.ps.BaseAddr(), + Addr: ch.Address()[:], + Data: ch.Data(), + Nonce: newNonce(), + } + msg, err := rlp.EncodeToBytes(cmsg) + if err != nil { + return err + } + log.Debug("send chunk", "addr", label(ch.Address()), "self", label(p.ps.BaseAddr())) + return p.ps.Send(ch.Address()[:], pssChunkTopic, msg) +} + +// needToSync checks if a chunk needs to be push-synced: +// * if not sent yet OR +// * if sent but more then retryInterval ago, so need resend +func (p *Pusher) needToSync(ch chunk.Chunk) bool { + item, found := p.pushed[ch.Address().Hex()] + // has been pushed already + if found { + // has synced already since subscribe called + if item.synced { + return false + } + // too early to retry + if item.sentAt.Add(retryInterval).After(time.Now()) { + return false + } + // first time encountered + } else { + // remember item + tag, _ := p.tags.Get(ch.TagID()) + item = &pushedItem{ + tag: tag, + } + // increment SENT count on tag if it exists + if item.tag != nil { + item.tag.Inc(chunk.StateSent) + } + // remember the item + p.pushed[ch.Address().Hex()] = item + } + item.sentAt = time.Now() + return true +} diff --git a/storage/pushsync/pusher_test.go b/storage/pushsync/pusher_test.go new file mode 100644 index 0000000000..743cb1db92 --- /dev/null +++ b/storage/pushsync/pusher_test.go @@ -0,0 +1,416 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . +package pushsync + +import ( + "context" + "encoding/binary" + "encoding/hex" + "flag" + "fmt" + "math/rand" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/p2p/enode" + "github.com/ethereum/go-ethereum/rlp" + "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/storage" + colorable "github.com/mattn/go-colorable" +) + +var ( + loglevel = flag.Int("loglevel", 3, "verbosity of logs") +) + +func init() { + flag.Parse() + log.PrintOrigins(true) + log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*loglevel), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) +} + +// loopback implements PubSub as a central subscription engine, +// ie a msg sent is received by all handlers registered for the topic +type loopBack struct { + async bool + addr []byte + handlers map[string][]func(msg []byte, p *p2p.Peer) error +} + +func newLoopBack(async bool) *loopBack { + return &loopBack{ + async: async, + addr: make([]byte, 32), + handlers: make(map[string][]func(msg []byte, p *p2p.Peer) error), + } +} + +// Register subscribes to a topic with a handler +func (lb *loopBack) Register(topic string, _ bool, handler func(msg []byte, p *p2p.Peer) error) func() { + lb.handlers[topic] = append(lb.handlers[topic], handler) + return func() {} +} + +// Send publishes a msg with a topic and directly calls registered handlers with +// that topic +func (lb *loopBack) Send(to []byte, topic string, msg []byte) error { + if lb.async { + go lb.send(to, topic, msg) + return nil + } + return lb.send(to, topic, msg) +} + +func (lb *loopBack) send(to []byte, topic string, msg []byte) error { + p := p2p.NewPeer(enode.ID{}, "", nil) + for _, handler := range lb.handlers[topic] { + if err := handler(msg, p); err != nil { + return err + } + } + return nil +} + +// BaseAddr needed to implement PubSub interface +func (lb *loopBack) BaseAddr() []byte { + return lb.addr +} + +// testPushSyncIndex mocks localstore and provides subscription and setting synced status +// it implements the DB interface +type testPushSyncIndex struct { + i, total int + tagIDs []uint32 // + tags *chunk.Tags + sent *sync.Map // to store time of send for retry + synced chan int // to check if right amount of chunks +} + +func newTestPushSyncIndex(chunkCnt int, tagIDs []uint32, tags *chunk.Tags, sent *sync.Map) *testPushSyncIndex { + return &testPushSyncIndex{ + i: 0, + total: chunkCnt, + tagIDs: tagIDs, + tags: tags, + sent: sent, + synced: make(chan int), + } +} + +// SubscribePush allows iteration on the hashes and mocks the behaviour of localstore +// push index +// we keep track of an index so that each call to SubscribePush knows where to start +// generating the new fake hashes +// Before the new fake hashes it iterates over hashes not synced yet +func (t *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chunk, func()) { + chunks := make(chan storage.Chunk) + tagCnt := len(t.tagIDs) + quit := make(chan struct{}) + stop := func() { close(quit) } + go func() { + // feed fake chunks into the db, hashes encode the order so that + // it can be traced + feed := func(i int) bool { + // generate fake hashes that encode the chunk order + addr := make([]byte, 32) + binary.BigEndian.PutUint64(addr, uint64(i)) + // remember when the chunk was put + // if sent again, dont modify the time + t.sent.Store(i, time.Now()) + // increment stored count on tag + tagID := t.tagIDs[i%tagCnt] + if tag, _ := t.tags.Get(tagID); tag != nil { + tag.Inc(chunk.StateStored) + } + select { + // chunks have no data and belong to tag i%tagCount + case chunks <- storage.NewChunk(addr, nil).WithTagID(tagID): + return true + case <-quit: + return false + } + } + // push the chunks already pushed but not yet synced + t.sent.Range(func(k, _ interface{}) bool { + log.Debug("resending", "cur", k) + return feed(k.(int)) + }) + // generate the new chunks from t.i + for t.i < t.total && feed(t.i) { + t.i++ + } + + log.Debug("sent all chunks", "total", t.total) + close(chunks) + }() + return chunks, stop +} + +func (t *testPushSyncIndex) Set(ctx context.Context, _ chunk.ModeSet, addrs ...storage.Address) error { + for _, addr := range addrs { + cur := int(binary.BigEndian.Uint64(addr[:8])) + t.sent.Delete(cur) + t.synced <- cur + log.Debug("set chunk synced", "cur", cur, "addr", addr) + } + return nil +} + +var ( + maxDelay = 210 // max delay in millisecond + minDelay = 1 // min delay in millisecond + retentionLimit = 200 // ~5% of msg lost +) + +// delayResponse when called mock connection/throughput +func delayResponse() bool { + delay := rand.Intn(maxDelay) + minDelay + time.Sleep(time.Duration(delay) * time.Millisecond) + return delay < retentionLimit +} + +// TestPusher tests the correct behaviour of Pusher +// in the context of inserting n chunks +// receipt response model: the pushed chunk's receipt is sent back +// after a random delay +// The test checks: +// - if sync function is called on chunks in order of insertion (FIFO) +// - repeated sending is attempted only if retryInterval time passed +// - already synced chunks are not resynced +// - if no more data inserted, the db is emptied shortly +func TestPusher(t *testing.T) { + timeout := 10 * time.Second + chunkCnt := 200 + tagCnt := 4 + + errc := make(chan error) + sent := &sync.Map{} + sendTimes := make(map[int]time.Time) + synced := make(map[int]int) + quit := make(chan struct{}) + defer close(quit) + + errf := func(s string, vals ...interface{}) { + select { + case errc <- fmt.Errorf(s, vals...): + case <-quit: + } + } + + ps := newLoopBack(false) + + max := 0 // the highest index sent so far + respond := func(msg []byte, _ *p2p.Peer) error { + chmsg, err := decodeChunkMsg(msg) + if err != nil { + errf("error decoding chunk message: %v", err) + return nil + } + // check outgoing chunk messages + cur := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) + if cur > max { + errf("incorrect order of chunks from db chunk #%d before #%d", cur, max) + return nil + } + v, found := sent.Load(cur) + previouslySentAt, repeated := sendTimes[cur] + if !found { + if !repeated { + errf("chunk #%d not sent but received", cur) + } + return nil + } + sentAt := v.(time.Time) + if repeated { + // expect at least retryInterval since previous push + if expectedAt := previouslySentAt.Add(retryInterval); expectedAt.After(sentAt) { + errf("resync chunk #%d too early. previously sent at %v, next at %v < expected at %v", cur, previouslySentAt, sentAt, expectedAt) + return nil + } + } + // remember the latest time sent + sendTimes[cur] = sentAt + max++ + // respond ~ mock storer protocol + go func() { + receipt := &receiptMsg{Addr: chmsg.Addr} + rmsg, err := rlp.EncodeToBytes(receipt) + if err != nil { + errf("error encoding receipt message: %v", err) + } + log.Debug("chunk sent", "addr", hex.EncodeToString(receipt.Addr)) + // random delay to allow retries + if !delayResponse() { + log.Debug("chunk/receipt lost", "addr", hex.EncodeToString(receipt.Addr)) + return + } + log.Debug("store chunk, send receipt", "addr", hex.EncodeToString(receipt.Addr)) + err = ps.Send(chmsg.Origin, pssReceiptTopic, rmsg) + if err != nil { + errf("error sending receipt message: %v", err) + } + }() + return nil + } + // register the respond function + ps.Register(pssChunkTopic, false, respond) + tags, tagIDs := setupTags(chunkCnt, tagCnt) + // construct the mock push sync index iterator + tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) + // start push syncing in a go routine + p := NewPusher(tp, ps, tags) + defer p.Close() + // collect synced chunks until all chunks synced + // wait on errc for errors on any thread + // otherwise time out + for { + select { + case i := <-tp.synced: + sent.Delete(i) + n := synced[i] + synced[i] = n + 1 + if len(synced) == chunkCnt { + expTotal := chunkCnt / tagCnt + checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) + return + } + case err := <-errc: + if err != nil { + t.Fatal(err) + } + case <-time.After(timeout): + t.Fatalf("timeout waiting for all chunks to be synced") + } + } + +} + +// setupTags constructs tags object create tagCnt - 1 tags +// the sequential fake chunk i will be tagged with i%tagCnt +func setupTags(chunkCnt, tagCnt int) (tags *chunk.Tags, tagIDs []uint32) { + // construct tags object + tags = chunk.NewTags() + // all but one tag is created + for i := 0; i < tagCnt-1; i++ { + tags.Create("", int64(chunkCnt/tagCnt)) + } + // extract tag ids + tags.Range(func(k, _ interface{}) bool { + tagIDs = append(tagIDs, k.(uint32)) + return true + }) + // add an extra for which no tag exists + return tags, append(tagIDs, 0) +} + +func checkTags(t *testing.T, expTotal int, tagIDs []uint32, tags *chunk.Tags) { + for _, tagID := range tagIDs { + tag, err := tags.Get(tagID) + if err != nil { + t.Fatalf("expected no error getting tag '%v', got %v", tagID, err) + } + n, total, err := tag.Status(chunk.StateSent) + if err != nil { + t.Fatalf("getting status for tag '%v', expected no error, got %v", tagID, err) + } + if int(n) != expTotal { + t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + } + if int(total) != expTotal { + t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + } + n, total, err = tag.Status(chunk.StateSynced) + if err != nil { + t.Fatalf("getting status for tag '%v', expected no error, got %v", tagID, err) + } + if int(n) != expTotal { + t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + } + if int(total) != expTotal { + t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + } + } +} + +type testStore struct { + store *sync.Map +} + +func (t *testStore) Put(_ context.Context, _ chunk.ModePut, ch chunk.Chunk) (bool, error) { + cur := binary.BigEndian.Uint64(ch.Address()[:8]) + var storedCnt uint32 = 1 + v, loaded := t.store.LoadOrStore(cur, &storedCnt) + if loaded { + atomic.AddUint32(v.(*uint32), 1) + } + return false, nil +} + +// TestPushSyncAndStoreWithLoopbackPubSub tests the push sync protocol +// push syncer node communicate with storers via mock PubSub +func TestPushSyncAndStoreWithLoopbackPubSub(t *testing.T) { + timeout := 10 * time.Second + chunkCnt := 2000 + tagCnt := 4 + storerCnt := 3 + sent := &sync.Map{} + store := &sync.Map{} + // mock pubsub messenger + ps := newLoopBack(true) + + tags, tagIDs := setupTags(chunkCnt, tagCnt) + // construct the mock push sync index iterator + tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) + // start push syncing in a go routine + p := NewPusher(tp, ps, tags) + defer p.Close() + + // set up a number of storers + storers := make([]*Storer, storerCnt) + for i := 0; i < storerCnt; i++ { + storers[i] = NewStorer(&testStore{store}, ps, p.PushReceipt) + } + + synced := 0 + for { + select { + case i := <-tp.synced: + synced++ + sent.Delete(i) + if synced == chunkCnt { + expTotal := chunkCnt / tagCnt + checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) + for i := uint64(0); i < uint64(chunkCnt); i++ { + v, ok := store.Load(i) + if !ok { + t.Fatalf("chunk %v not stored", i) + } + if cnt := *(v.(*uint32)); cnt != uint32(storerCnt) { + t.Fatalf("chunk %v expected to be saved %v times, got %v", i, storerCnt, cnt) + } + } + return + } + case <-time.After(timeout): + t.Fatalf("timeout waiting for all chunks to be synced") + } + } + +} diff --git a/storage/pushsync/pushsync_simulation_test.go b/storage/pushsync/pushsync_simulation_test.go new file mode 100644 index 0000000000..fdce2bce46 --- /dev/null +++ b/storage/pushsync/pushsync_simulation_test.go @@ -0,0 +1,280 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package pushsync + +import ( + "context" + "fmt" + "io/ioutil" + "math/rand" + "os" + "sync" + "testing" + "time" + + "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/node" + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/p2p/simulations/adapters" + "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/log" + "github.com/ethersphere/swarm/network" + "github.com/ethersphere/swarm/network/simulation" + "github.com/ethersphere/swarm/network/stream" + "github.com/ethersphere/swarm/pss" + "github.com/ethersphere/swarm/state" + "github.com/ethersphere/swarm/storage" + "github.com/ethersphere/swarm/storage/localstore" +) + +var ( + bucketKeyPushSyncer = simulation.BucketKey("pushsyncer") + bucketKeyNetStore = simulation.BucketKey("netstore") +) + +// test syncer using pss +// the test +// * creates a simulation with connectivity loaded from a snapshot +// * for each trial, two nodes are chosen randomly, an uploader and a downloader +// * uploader uploads a number of chunks +// * wait until the uploaded chunks are synced +// * downloader downloads the chunk +// Trials are run concurrently +func TestPushSyncSimulation(t *testing.T) { + nodeCnt := 4 + chunkCnt := 500 + trials := 10 + err := testSyncerWithPubSub(nodeCnt, chunkCnt, trials, newServiceFunc) + if err != nil { + t.Fatal(err) + } +} + +func testSyncerWithPubSub(nodeCnt, chunkCnt, trials int, sf simulation.ServiceFunc) error { + sim := simulation.New(map[string]simulation.ServiceFunc{ + "streamer": sf, + }) + defer sim.Close() + + ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + defer cancel() + err := sim.UploadSnapshot(ctx, fmt.Sprintf("../../network/stream/testing/snapshot_%d.json", nodeCnt)) + if err != nil { + return err + } + log.Info("Snapshot loaded") + + result := sim.Run(ctx, func(ctx context.Context, sim *simulation.Simulation) error { + errc := make(chan error) + for i := 0; i < trials; i++ { + go uploadAndDownload(ctx, sim, errc, nodeCnt, chunkCnt, i) + } + i := 0 + for err := range errc { + if err != nil { + return err + } + i++ + if i >= trials { + break + } + } + return nil + }) + + if result.Error != nil { + return fmt.Errorf("simulation error: %v", result.Error) + } + return nil +} + +// pickNodes selects 2 distinct +func pickNodes(n int) (i, j int) { + i = rand.Intn(n) + j = rand.Intn(n - 1) + if j >= i { + j++ + } + return +} + +func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, errc chan error, nodeCnt, chunkCnt, i int) { + // chose 2 random nodes as uploader and downloader + u, d := pickNodes(nodeCnt) + // setup uploader node + uid := sim.UpNodeIDs()[u] + val, _ := sim.NodeItem(uid, bucketKeyPushSyncer) + p := val.(*Pusher) + // setup downloader node + did := sim.UpNodeIDs()[d] + // the created tag indicates the uploader and downloader nodes + tagname := fmt.Sprintf("tag-%v-%v-%d", label(uid[:]), label(did[:]), i) + log.Debug("uploading", "peer", uid, "chunks", chunkCnt, "tagname", tagname) + tag, what, err := upload(ctx, p.store.(*localstore.DB), p.tags, tagname, chunkCnt) + if err != nil { + select { + case errc <- err: + case <-ctx.Done(): + return + } + return + } + + // wait till synced + for { + n, total, err := tag.Status(chunk.StateSynced) + if err == nil && n == total { + break + } + time.Sleep(100 * time.Millisecond) + } + + log.Debug("synced", "peer", uid, "chunks", chunkCnt, "tagname", tagname) + log.Debug("downloading", "peer", did, "chunks", chunkCnt, "tagname", tagname) + val, _ = sim.NodeItem(did, bucketKeyNetStore) + netstore := val.(*storage.NetStore) + select { + case errc <- download(ctx, netstore, what): + case <-ctx.Done(): + } + log.Debug("downloaded", "peer", did, "chunks", chunkCnt, "tagname", tagname) +} + +// newServiceFunc constructs a minimal service needed for a simulation test for Push Sync, namely: +// localstore, netstore, stream and pss +func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Service, func(), error) { + // setup localstore + n := ctx.Config.Node() + addr := network.NewAddr(n) + dir, err := ioutil.TempDir("", "localstore-test") + if err != nil { + return nil, nil, err + } + lstore, err := localstore.New(dir, addr.Over(), nil) + if err != nil { + os.RemoveAll(dir) + return nil, nil, err + } + // setup netstore + netStore, err := storage.NewNetStore(lstore, nil) + if err != nil { + return nil, nil, err + } + + // setup pss + kadParams := network.NewKadParams() + kad := network.NewKademlia(addr.Over(), kadParams) + bucket.Store(simulation.BucketKeyKademlia, kad) + + privKey, err := crypto.GenerateKey() + pssp := pss.NewPssParams().WithPrivateKey(privKey) + ps, err := pss.NewPss(kad, pssp) + if err != nil { + return nil, nil, err + } + + // streamer + delivery := stream.NewDelivery(kad, netStore) + netStore.NewNetFetcherFunc = network.NewFetcherFactory(delivery.RequestFromPeers, true).New + bucket.Store(bucketKeyNetStore, netStore) + + noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled} + r := stream.NewRegistry(addr.ID(), delivery, netStore, state.NewInmemoryStore(), noSyncing, nil) + + pubSub := pss.NewPubSub(ps) + + // set up syncer + p := NewPusher(lstore, pubSub, chunk.NewTags()) + bucket.Store(bucketKeyPushSyncer, p) + + // setup storer + s := NewStorer(lstore, pubSub, p.PushReceipt) + + cleanup := func() { + p.Close() + s.Close() + netStore.Close() + r.Close() + os.RemoveAll(dir) + } + + return &StreamerAndPss{r, ps}, cleanup, nil +} + +// implements the node.Service interface +type StreamerAndPss struct { + *stream.Registry + pss *pss.Pss +} + +func (s *StreamerAndPss) Protocols() []p2p.Protocol { + return append(s.Registry.Protocols(), s.pss.Protocols()...) +} + +func (s *StreamerAndPss) Start(srv *p2p.Server) error { + err := s.Registry.Start(srv) + if err != nil { + return err + } + return s.pss.Start(srv) +} + +func (s *StreamerAndPss) Stop() error { + err := s.Registry.Stop() + if err != nil { + return err + } + return s.pss.Stop() +} + +func upload(ctx context.Context, store Store, tags *chunk.Tags, tagname string, n int) (tag *chunk.Tag, addrs []storage.Address, err error) { + tag, err = tags.New(tagname, int64(n)) + if err != nil { + return nil, nil, err + } + for i := 0; i < n; i++ { + ch := storage.GenerateRandomChunk(int64(chunk.DefaultSize)) + addrs = append(addrs, ch.Address()) + store.Put(ctx, chunk.ModePutUpload, ch.WithTagID(tag.Uid)) + tag.Inc(chunk.StateStored) + } + return tag, addrs, nil +} + +func download(ctx context.Context, store *storage.NetStore, addrs []storage.Address) error { + errc := make(chan error) + for _, addr := range addrs { + go func(addr storage.Address) { + _, err := store.Get(ctx, chunk.ModeGetRequest, addr) + select { + case errc <- err: + case <-ctx.Done(): + } + }(addr) + } + i := 0 + for err := range errc { + if err != nil { + return err + } + i++ + if i == len(addrs) { + break + } + } + return nil +} diff --git a/storage/pushsync/storer.go b/storage/pushsync/storer.go new file mode 100644 index 0000000000..a54e2ca925 --- /dev/null +++ b/storage/pushsync/storer.go @@ -0,0 +1,119 @@ +// Copyright 2019 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package pushsync + +import ( + "bytes" + "context" + "encoding/hex" + "fmt" + + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/rlp" + "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/log" + "github.com/ethersphere/swarm/storage" +) + +// Store is the storage interface to save chunks +// NetStore implements this interface +type Store interface { + Put(context.Context, chunk.ModePut, chunk.Chunk) (bool, error) +} + +// Storer is the object used by the push-sync server side protocol +type Storer struct { + store Store // store to put chunks in, and retrieve them + ps PubSub // pubsub interface to receive chunks and send receipts + deregister func() // deregister the registered handler when Storer is closed + pushReceipt func(addr []byte) // to be called... +} + +// NewStorer constructs a Storer +// Storer run storer nodes to handle the reception of push-synced chunks +// that fall within their area of responsibility. +// The protocol makes sure that +// - the chunks are stored and synced to their nearest neighbours and +// - a statement of custody receipt is sent as a response to the originator +// it sets a cancel function that deregisters the handler +func NewStorer(store Store, ps PubSub, pushReceipt func(addr []byte)) *Storer { + s := &Storer{ + store: store, + ps: ps, + pushReceipt: pushReceipt, + } + s.deregister = ps.Register(pssChunkTopic, true, func(msg []byte, _ *p2p.Peer) error { + return s.handleChunkMsg(msg) + }) + return s +} + +// Close needs to be called to deregister the handler +func (s *Storer) Close() { + s.deregister() +} + +// handleChunkMsg is called by the pss dispatcher on pssChunkTopic msgs +// - deserialises chunkMsg and +// - calls storer.processChunkMsg function +func (s *Storer) handleChunkMsg(msg []byte) error { + chmsg, err := decodeChunkMsg(msg) + if err != nil { + return err + } + log.Debug("Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin), "self", fmt.Sprintf("%x", s.ps.BaseAddr())) + return s.processChunkMsg(chmsg) +} + +// processChunkMsg processes a chunk received via pss pssChunkTopic +// these chunk messages are sent to their address as destination +// using neighbourhood addressing. Therefore nodes only handle +// chunks that fall within their area of responsibility. +// Upon receiving the chunk is saved and a statement of custody +// receipt message is sent as a response to the originator. +func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { + // TODO: double check if it falls in area of responsibility + ch := storage.NewChunk(chmsg.Addr, chmsg.Data) + if _, err := s.store.Put(context.TODO(), chunk.ModePutSync, ch); err != nil { + return err + } + // TODO: check if originator or relayer is a nearest neighbour then return + // otherwise send back receipt + return s.sendReceiptMsg(chmsg) +} + +// sendReceiptMsg sends a statement of custody receipt message +// to the originator of a push-synced chunk message. +// Including a unique nonce makes the receipt immune to deduplication cache +func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { + // if origin is self, use direct channel, no pubsub send needed + if bytes.Equal(chmsg.Origin, s.ps.BaseAddr()) { + go s.pushReceipt(chmsg.Addr) + return nil + } + rmsg := &receiptMsg{ + Addr: chmsg.Addr, + Nonce: newNonce(), + } + msg, err := rlp.EncodeToBytes(rmsg) + if err != nil { + return err + } + to := chmsg.Origin + log.Debug("send receipt", "addr", label(rmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) + return s.ps.Send(to, pssReceiptTopic, msg) +} diff --git a/swarm.go b/swarm.go index dc8952063e..60505d1246 100644 --- a/swarm.go +++ b/swarm.go @@ -58,6 +58,7 @@ import ( "github.com/ethersphere/swarm/storage/localstore" "github.com/ethersphere/swarm/storage/mock" "github.com/ethersphere/swarm/storage/pin" + "github.com/ethersphere/swarm/storage/pushsync" "github.com/ethersphere/swarm/swap" "github.com/ethersphere/swarm/tracing" ) @@ -84,6 +85,8 @@ type Swarm struct { netStore *storage.NetStore sfs *fuse.SwarmFS // need this to cleanup all the active mounts on node exit ps *pss.Pss + pushSync *pushsync.Pusher + storer *pushsync.Storer swap *swap.Swap stateStore *state.DBStore tags *chunk.Tags @@ -241,7 +244,11 @@ func NewSwarm(config *api.Config, mockStore *mock.NodeStore) (self *Swarm, err e pss.SetHandshakeController(self.ps, pss.NewHandshakeParams()) } - self.api = api.NewAPI(self.fileStore, self.dns, feedsHandler, self.privateKey, self.tags) + pubsub := pss.NewPubSub(self.ps) + self.pushSync = pushsync.NewPusher(localStore, pubsub, tags) + self.storer = pushsync.NewStorer(localStore, pubsub) + + self.api = api.NewAPI(self.fileStore, self.dns, feedsHandler, self.privateKey, tags) // Instantiate the pinAPI object with the already opened localstore self.pinAPI = pin.NewAPI(localStore, self.stateStore, self.config.FileStoreParams, self.tags, self.api) @@ -491,6 +498,9 @@ func (s *Swarm) Stop() error { s.stateStore.Close() } + s.pushSync.Close() + s.storer.Close() + for _, cleanF := range s.cleanupFuncs { err = cleanF() if err != nil { From ea82e7d4a0c297f94b29a149842f7daa382c0c4d Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Tue, 18 Jun 2019 15:49:54 +0200 Subject: [PATCH 02/22] storage/pushsync: update NetStore api from master --- storage/pushsync/pushsync_simulation_test.go | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/storage/pushsync/pushsync_simulation_test.go b/storage/pushsync/pushsync_simulation_test.go index fdce2bce46..1da32f17a4 100644 --- a/storage/pushsync/pushsync_simulation_test.go +++ b/storage/pushsync/pushsync_simulation_test.go @@ -29,6 +29,7 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/node" "github.com/ethereum/go-ethereum/p2p" + "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/p2p/simulations/adapters" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" @@ -170,10 +171,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } // setup netstore - netStore, err := storage.NewNetStore(lstore, nil) - if err != nil { - return nil, nil, err - } + netStore := storage.NewNetStore(lstore, enode.ID{}) // setup pss kadParams := network.NewKadParams() @@ -189,7 +187,8 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic // streamer delivery := stream.NewDelivery(kad, netStore) - netStore.NewNetFetcherFunc = network.NewFetcherFactory(delivery.RequestFromPeers, true).New + netStore.RemoteGet = delivery.RequestFromPeers + bucket.Store(bucketKeyNetStore, netStore) noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled} @@ -259,7 +258,7 @@ func download(ctx context.Context, store *storage.NetStore, addrs []storage.Addr errc := make(chan error) for _, addr := range addrs { go func(addr storage.Address) { - _, err := store.Get(ctx, chunk.ModeGetRequest, addr) + _, err := store.Get(ctx, chunk.ModeGetRequest, storage.NewRequest(addr)) select { case errc <- err: case <-ctx.Done(): From 930fda6ae54ec25d4be48f4931c87c1c1c79db27 Mon Sep 17 00:00:00 2001 From: acud Date: Wed, 19 Jun 2019 12:01:28 +0200 Subject: [PATCH 03/22] storage/pushsync: add sleeps and a bit more tracing, change subscription wait delay --- storage/pushsync/pushsync_simulation_test.go | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/storage/pushsync/pushsync_simulation_test.go b/storage/pushsync/pushsync_simulation_test.go index 1da32f17a4..c7c9fc6e59 100644 --- a/storage/pushsync/pushsync_simulation_test.go +++ b/storage/pushsync/pushsync_simulation_test.go @@ -59,13 +59,14 @@ func TestPushSyncSimulation(t *testing.T) { nodeCnt := 4 chunkCnt := 500 trials := 10 - err := testSyncerWithPubSub(nodeCnt, chunkCnt, trials, newServiceFunc) + err := testSyncerWithPubSub(t, nodeCnt, chunkCnt, trials, newServiceFunc) if err != nil { t.Fatal(err) } } -func testSyncerWithPubSub(nodeCnt, chunkCnt, trials int, sf simulation.ServiceFunc) error { +func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, trials int, sf simulation.ServiceFunc) error { + t.Helper() sim := simulation.New(map[string]simulation.ServiceFunc{ "streamer": sf, }) @@ -75,11 +76,12 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, trials int, sf simulation.ServiceFu defer cancel() err := sim.UploadSnapshot(ctx, fmt.Sprintf("../../network/stream/testing/snapshot_%d.json", nodeCnt)) if err != nil { - return err + t.Fatal(err) } log.Info("Snapshot loaded") - + time.Sleep(2 * time.Second) result := sim.Run(ctx, func(ctx context.Context, sim *simulation.Simulation) error { + time.Sleep(2 * time.Second) errc := make(chan error) for i := 0; i < trials; i++ { go uploadAndDownload(ctx, sim, errc, nodeCnt, chunkCnt, i) @@ -98,7 +100,7 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, trials int, sf simulation.ServiceFu }) if result.Error != nil { - return fmt.Errorf("simulation error: %v", result.Error) + t.Fatalf("simulation error: %v", result.Error) } return nil } @@ -191,7 +193,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic bucket.Store(bucketKeyNetStore, netStore) - noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled} + noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled, SyncUpdateDelay: 50 * time.Millisecond} r := stream.NewRegistry(addr.ID(), delivery, netStore, state.NewInmemoryStore(), noSyncing, nil) pubSub := pss.NewPubSub(ps) From a0e01d9b752b6d98f55773ef6a887cc29d6b1a76 Mon Sep 17 00:00:00 2001 From: zelig Date: Wed, 26 Jun 2019 13:33:11 +0200 Subject: [PATCH 04/22] chunk; fix "already exists" error tags.Uid no need for rng obj --- chunk/tags.go | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/chunk/tags.go b/chunk/tags.go index 6b216d2b5c..8ee06c1b4e 100644 --- a/chunk/tags.go +++ b/chunk/tags.go @@ -30,14 +30,12 @@ import ( // Tags hold tag information indexed by a unique random uint32 type Tags struct { tags *sync.Map - rng *rand.Rand } // NewTags creates a tags object func NewTags() *Tags { return &Tags{ tags: &sync.Map{}, - rng: rand.New(rand.NewSource(time.Now().Unix())), } } @@ -45,7 +43,7 @@ func NewTags() *Tags { // it returns an error if the tag with this name already exists func (ts *Tags) Create(s string, total int64) (*Tag, error) { t := &Tag{ - Uid: ts.rng.Uint32(), + Uid: uint32(rand.Int31()), Name: s, StartedAt: time.Now(), Total: total, From cd1797717ce54e8d622201c253c195ce4f6faa6c Mon Sep 17 00:00:00 2001 From: zelig Date: Sat, 29 Jun 2019 13:09:40 +0200 Subject: [PATCH 05/22] storage/pushsync: fix storer initialisation - storer needs to take netstore not localstore to put the chunk so that fetchers created earlier could respond --- storage/pushsync/pushsync_simulation_test.go | 2 +- storage/pushsync/storer.go | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/storage/pushsync/pushsync_simulation_test.go b/storage/pushsync/pushsync_simulation_test.go index c7c9fc6e59..c6119f2ac2 100644 --- a/storage/pushsync/pushsync_simulation_test.go +++ b/storage/pushsync/pushsync_simulation_test.go @@ -203,7 +203,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic bucket.Store(bucketKeyPushSyncer, p) // setup storer - s := NewStorer(lstore, pubSub, p.PushReceipt) + s := NewStorer(netStore, pubSub, p.PushReceipt) cleanup := func() { p.Close() diff --git a/storage/pushsync/storer.go b/storage/pushsync/storer.go index a54e2ca925..c0a966ac8b 100644 --- a/storage/pushsync/storer.go +++ b/storage/pushsync/storer.go @@ -91,6 +91,7 @@ func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { if _, err := s.store.Put(context.TODO(), chunk.ModePutSync, ch); err != nil { return err } + log.Debug("push sync storer", "addr", label(chmsg.Addr), "to", label(chmsg.Origin), "self", hex.EncodeToString(s.ps.BaseAddr())) // TODO: check if originator or relayer is a nearest neighbour then return // otherwise send back receipt return s.sendReceiptMsg(chmsg) @@ -114,6 +115,6 @@ func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { return err } to := chmsg.Origin - log.Debug("send receipt", "addr", label(rmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) + log.Debug("send receipt", "addr", label(chmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) return s.ps.Send(to, pssReceiptTopic, msg) } From 1d6ee6ba7be8af020c11d1c70f0bc72315e93e95 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Wed, 15 May 2019 12:55:43 +0200 Subject: [PATCH 06/22] swarm: push sync storage/pushsync: update NetStore api from master storage/pushsync: add sleeps and a bit more tracing, change subscription wait delay network: try sending receipt only if there is no closer peer storage/pushsync: use netstore, rather than localstore storage/netstore: logs with node id storage/pushsync: opentracing storage/pushsync: propagate origin on receipts is push synced - smoke test network: kademlia closer peer storage: very high retry timeout measure send chunk rlp timer pss timers and goroutine sendChunk traces for chunsk in localstore and subscribepush try minbinsize: 3 increase search timeout ; move tracing before nil check link netstore and delivery rename tag New to tag Create swarm-smoke: fix check max prox hosts for pull/push sync modes tag roundtrip wip more logs kad as part of pusher? kad to storer; revert pss change metrics to pss outbox len metric emit metrics once every 10sec. pss: refactor storage/pushsync: closer than me trace chunk: adding XOR comparison disable pushsync tests, as they are not setting up kad properly --- api/http/server.go | 36 ++-- api/inspector.go | 17 ++ chunk/chunk.go | 16 ++ chunk/tag.go | 24 +++ chunk/tags.go | 3 + cmd/swarm-smoke/upload_and_sync.go | 3 +- network/kademlia.go | 48 +++++ network/timeouts/timeouts.go | 2 +- storage/localstore/subscription_push.go | 2 + storage/netstore.go | 4 +- storage/pushsync/protocol.go | 5 +- storage/pushsync/pusher.go | 198 ++++++++++++++----- storage/pushsync/pusher_test.go | 11 +- storage/pushsync/pushsync_simulation_test.go | 31 ++- storage/pushsync/storer.go | 52 ++++- swarm.go | 2 +- 16 files changed, 347 insertions(+), 107 deletions(-) diff --git a/api/http/server.go b/api/http/server.go index 2a7113e3f8..1a506cf34b 100644 --- a/api/http/server.go +++ b/api/http/server.go @@ -279,10 +279,10 @@ func (s *Server) HandlePostRaw(w http.ResponseWriter, r *http.Request) { ruid := GetRUID(r.Context()) log.Debug("handle.post.raw", "ruid", ruid) - tagUid := sctx.GetTag(r.Context()) - tag, err := s.api.Tags.Get(tagUid) + tagUID := sctx.GetTag(r.Context()) + tag, err := s.api.Tags.Get(tagUID) if err != nil { - log.Error("handle post raw got an error retrieving tag for DoneSplit", "tagUid", tagUid, "err", err) + log.Error("handle post raw got an error retrieving tag for DoneSplit", "tagUID", tagUID, "err", err) } postRawCount.Inc(1) @@ -337,7 +337,7 @@ func (s *Server) HandlePostRaw(w http.ResponseWriter, r *http.Request) { } w.Header().Set("Content-Type", "text/plain") - w.Header().Set(TagHeaderName, fmt.Sprint(tagUid)) + w.Header().Set(TagHeaderName, fmt.Sprint(tagUID)) w.WriteHeader(http.StatusOK) fmt.Fprint(w, addr) } @@ -352,14 +352,16 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { log.Debug("handle.post.files", "ruid", ruid) postFilesCount.Inc(1) - ctx, sp := spancontext.StartSpan(r.Context(), "handle.post.files") - defer sp.Finish() + tagUID := sctx.GetTag(r.Context()) + tag, err := s.api.Tags.Get(tagUID) + if err != nil { + log.Error("handle post raw got an error retrieving tag", "tagUID", tagUID, "err", err) + } - quitChan := make(chan struct{}) - defer close(quitChan) + ctx := r.Context() - // periodically monitor the tag for this upload and log its state to the `handle.post.files` span - go periodicTagTrace(s.api.Tags, sctx.GetTag(ctx), quitChan, sp) + _, sp := spancontext.StartSpan(tag.Tctx, "http.post") + defer sp.Finish() contentType, params, err := mime.ParseMediaType(r.Header.Get("Content-Type")) if err != nil { @@ -417,10 +419,10 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { return } - tagUid := sctx.GetTag(r.Context()) - tag, err := s.api.Tags.Get(tagUid) + tagUID = sctx.GetTag(r.Context()) + tag, err = s.api.Tags.Get(tagUID) if err != nil { - log.Error("got an error retrieving tag for DoneSplit", "tagUid", tagUid, "err", err) + log.Error("got an error retrieving tag for DoneSplit", "tagUID", tagUID, "err", err) } log.Debug("done splitting, setting tag total", "SPLIT", tag.Get(chunk.StateSplit), "TOTAL", tag.TotalCounter()) @@ -439,7 +441,7 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { log.Debug("stored content", "ruid", ruid, "key", newAddr) w.Header().Set("Content-Type", "text/plain") - w.Header().Set(TagHeaderName, fmt.Sprint(tagUid)) + w.Header().Set(TagHeaderName, fmt.Sprint(tagUID)) w.WriteHeader(http.StatusOK) fmt.Fprint(w, newAddr) } @@ -1148,11 +1150,11 @@ func isDecryptError(err error) bool { } // periodicTagTrace queries the tag every 2 seconds and logs its state to the span -func periodicTagTrace(tags *chunk.Tags, tagUid uint32, q chan struct{}, sp opentracing.Span) { +func periodicTagTrace(tags *chunk.Tags, tagUID uint32, q chan struct{}, sp opentracing.Span) { f := func() { - tag, err := tags.Get(tagUid) + tag, err := tags.Get(tagUID) if err != nil { - log.Error("error while getting tag", "tagUid", tagUid, "err", err) + log.Error("error while getting tag", "tagUID", tagUID, "err", err) } sp.LogFields(olog.String("tag state", fmt.Sprintf("split=%d stored=%d seen=%d synced=%d", tag.Get(chunk.StateSplit), tag.Get(chunk.StateStored), tag.Get(chunk.StateSeen), tag.Get(chunk.StateSynced)))) diff --git a/api/inspector.go b/api/inspector.go index 24a98cc9f2..88d5249557 100644 --- a/api/inspector.go +++ b/api/inspector.go @@ -53,6 +53,23 @@ func (i *Inspector) KademliaInfo() network.KademliaInfo { return i.hive.KademliaInfo() } +func (i *Inspector) IsPushSynced(tagname string) bool { + log.Info("is push synced", "tagname", tagname) + tags := i.api.Tags.All() + + for _, t := range tags { + if t.Name == tagname { + ds := t.DoneSyncing() + + log.Debug("found tag", "tagname", tagname, "done-syncing", ds) + + return ds + } + } + + return false +} + func (i *Inspector) IsPullSyncing() bool { t := i.stream.LastReceivedChunkTime() diff --git a/chunk/chunk.go b/chunk/chunk.go index 50de9c1c56..765ede4be4 100644 --- a/chunk/chunk.go +++ b/chunk/chunk.go @@ -119,6 +119,22 @@ func (a *Address) UnmarshalJSON(value []byte) error { return nil } +// XOR stores (a xor b) in dst, stopping when the end of any slice is +// reached. It returns the number of bytes xor'd. +func XOR(dst, a, b []byte) int { + n := len(a) + if len(b) < n { + n = len(b) + } + if len(dst) < n { + n = len(dst) + } + for i := 0; i < n; i++ { + dst[i] = a[i] ^ b[i] + } + return n +} + // Proximity returns the proximity order of the MSB distance between x and y // // The distance metric MSB(x, y) of two equal length byte sequences x an y is the diff --git a/chunk/tag.go b/chunk/tag.go index 7f1c3a1e68..1d0be8bee6 100644 --- a/chunk/tag.go +++ b/chunk/tag.go @@ -17,10 +17,14 @@ package chunk import ( + "context" "encoding/binary" "errors" "sync/atomic" "time" + + "github.com/ethersphere/swarm/spancontext" + "github.com/opentracing/opentracing-go" ) var ( @@ -53,6 +57,10 @@ type Tag struct { Sent int64 // number of chunks sent for push syncing Synced int64 // number of chunks synced with proof StartedAt time.Time // tag started to calculate ETA + + // end-to-end tag tracing + Tctx context.Context // tracing context + Span opentracing.Span // tracing root span TODO: should it be exported? } // New creates a new tag, stores it by the name and returns it @@ -64,9 +72,15 @@ func NewTag(uid uint32, s string, total int64) *Tag { StartedAt: time.Now(), Total: total, } + + t.Tctx, t.Span = spancontext.StartSpan(context.Background(), "new.upload.tag") return t } +func (t *Tag) FinishRootSpan() { + t.Span.Finish() +} + // Inc increments the count for a state func (t *Tag) Inc(state State) { var v *int64 @@ -108,6 +122,16 @@ func (t *Tag) TotalCounter() int64 { return atomic.LoadInt64(&t.Total) } +func (t *Tag) DoneSyncing() bool { + n, total, err := t.Status(StateSynced) + + if err == nil && n == total { + return true + } + + return false +} + // DoneSplit sets total count to SPLIT count and sets the associated swarm hash for this tag // is meant to be called when splitter finishes for input streams of unknown size func (t *Tag) DoneSplit(address Address) int64 { diff --git a/chunk/tags.go b/chunk/tags.go index 8ee06c1b4e..4df6500d8f 100644 --- a/chunk/tags.go +++ b/chunk/tags.go @@ -25,6 +25,7 @@ import ( "time" "github.com/ethersphere/swarm/sctx" + "github.com/ethersphere/swarm/spancontext" ) // Tags hold tag information indexed by a unique random uint32 @@ -51,6 +52,8 @@ func (ts *Tags) Create(s string, total int64) (*Tag, error) { if _, loaded := ts.tags.LoadOrStore(t.Uid, t); loaded { return nil, errExists } + + t.Tctx, t.Span = spancontext.StartSpan(context.Background(), "new.upload.tag") return t, nil } diff --git a/cmd/swarm-smoke/upload_and_sync.go b/cmd/swarm-smoke/upload_and_sync.go index 5f0a045da6..d803e35d04 100644 --- a/cmd/swarm-smoke/upload_and_sync.go +++ b/cmd/swarm-smoke/upload_and_sync.go @@ -37,7 +37,6 @@ import ( "github.com/ethersphere/swarm/testutil" "github.com/pborman/uuid" "golang.org/x/sync/errgroup" - cli "gopkg.in/urfave/cli.v1" ) @@ -208,6 +207,8 @@ func checkChunksVsMostProxHosts(addrs []storage.Address, allHostChunks map[strin } } + log.Trace("sync mode", "sync mode", syncMode) + if syncMode == "pullsync" || syncMode == "both" { for _, maxProxHost := range maxProxHosts { if allHostChunks[maxProxHost][i] == '0' { diff --git a/network/kademlia.go b/network/kademlia.go index 6af58d6a74..f8566b407c 100644 --- a/network/kademlia.go +++ b/network/kademlia.go @@ -27,6 +27,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/metrics" + "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/pot" sv "github.com/ethersphere/swarm/version" @@ -568,6 +569,53 @@ func (k *Kademlia) callable(e *entry) bool { return true } +func (k *Kademlia) CloserPeerThanMeXOR(addr []byte) bool { + var ret bool + + myDistance := make([]byte, 32) + chunk.XOR(myDistance, k.BaseAddr(), addr) + + // iterate connection in kademlia + k.EachConn(addr, 255, func(p *Peer, po int) bool { + if !p.BzzPeer.Peer.HasCap("pss") { + return true + } + + otherDistance := make([]byte, 32) + chunk.XOR(otherDistance, p.Over(), addr) + + if bytes.Compare(myDistance, otherDistance) == 1 { + ret = true + return false + } + + return true + }) + + return ret +} + +func (k *Kademlia) CloserPeerThanMe(addr []byte) bool { + var ret bool + + myPo, _ := Pof(k.BaseAddr(), addr, 0) + + // iterate connection in kademlia + k.EachConn(addr, 255, func(p *Peer, po int) bool { + if !p.BzzPeer.Peer.HasCap("pss") { + return true + } + + if po > myPo { + ret = true + } + + return false + }) + + return ret +} + // BaseAddr return the kademlia base address func (k *Kademlia) BaseAddr() []byte { return k.base diff --git a/network/timeouts/timeouts.go b/network/timeouts/timeouts.go index b92af3b47b..ca71d79584 100644 --- a/network/timeouts/timeouts.go +++ b/network/timeouts/timeouts.go @@ -11,7 +11,7 @@ var FailedPeerSkipDelay = 20 * time.Second var FetcherGlobalTimeout = 10 * time.Second // SearchTimeout is the max time requests wait for a peer to deliver a chunk, after which another peer is tried -var SearchTimeout = 500 * time.Millisecond +var SearchTimeout = 2000 * time.Millisecond // SyncerClientWaitTimeout is the max time a syncer client waits for a chunk to be delivered during syncing var SyncerClientWaitTimeout = 20 * time.Second diff --git a/storage/localstore/subscription_push.go b/storage/localstore/subscription_push.go index 94da228d30..07821adf97 100644 --- a/storage/localstore/subscription_push.go +++ b/storage/localstore/subscription_push.go @@ -18,6 +18,7 @@ package localstore import ( "context" + "fmt" "sync" "time" @@ -80,6 +81,7 @@ func (db *DB) SubscribePush(ctx context.Context) (c <-chan chunk.Chunk, stop fun // set next iteration start item // when its chunk is successfully sent to channel sinceItem = &item + log.Trace("subscribe.push", "ref", fmt.Sprintf("%x", sinceItem.Address), "binid", sinceItem.BinID) return false, nil case <-stopChan: // gracefully stop the iteration diff --git a/storage/netstore.go b/storage/netstore.go index cf0ee873d1..c3c28b9838 100644 --- a/storage/netstore.go +++ b/storage/netstore.go @@ -236,7 +236,9 @@ func (n *NetStore) RemoteFetch(ctx context.Context, req *Request, fi *Fetcher) e "remote.fetch") osp.LogFields(olog.String("ref", ref.String())) - n.logger.Trace("remote.fetch", "ref", ref) + ctx = context.WithValue(ctx, "remote.fetch", osp) + + log.Trace("remote.fetch", "ref", ref) currentPeer, err := n.RemoteGet(ctx, req, n.LocalID) if err != nil { diff --git a/storage/pushsync/protocol.go b/storage/pushsync/protocol.go index 3285f84833..6476d422e2 100644 --- a/storage/pushsync/protocol.go +++ b/storage/pushsync/protocol.go @@ -48,8 +48,9 @@ type chunkMsg struct { // it is currently a notification only (contains no proof) sent to the originator // Nonce is there to make multiple responses immune to deduplication cache type receiptMsg struct { - Addr []byte - Nonce []byte + Addr []byte + Origin []byte + Nonce []byte } func decodeChunkMsg(msg []byte) (*chunkMsg, error) { diff --git a/storage/pushsync/pusher.go b/storage/pushsync/pusher.go index d544ebaced..13a4c8e919 100644 --- a/storage/pushsync/pusher.go +++ b/storage/pushsync/pusher.go @@ -18,6 +18,7 @@ package pushsync import ( "context" + "fmt" "time" "github.com/ethereum/go-ethereum/metrics" @@ -25,7 +26,10 @@ import ( "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" + "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" + "github.com/opentracing/opentracing-go" + olog "github.com/opentracing/opentracing-go/log" ) // DB interface implemented by localstore @@ -39,16 +43,17 @@ type DB interface { // Pusher takes care of the push syncing type Pusher struct { - store DB // localstore DB - tags *chunk.Tags // tags to update counts - quit chan struct{} // channel to signal quitting on all loops - pushed map[string]*pushedItem // cache of items push-synced - receipts chan chunk.Address // channel to receive receipts - ps PubSub // PubSub interface to send chunks and receive receipts + nnf func(storage.Address) bool // determines if self address is closer to a chunk + store DB // localstore DB + tags *chunk.Tags // tags to update counts + quit chan struct{} // channel to signal quitting on all loops + pushed map[string]*pushedItem // cache of items push-synced + receipts chan *receiptMsg // channel to receive receipts + ps PubSub // PubSub interface to send chunks and receive receipts } var ( - retryInterval = 2 * time.Second // seconds to wait before retry sync + retryInterval = 30 * time.Second // seconds to wait before retry sync ) // pushedItem captures the info needed for the pusher about a chunk during the @@ -57,6 +62,9 @@ type pushedItem struct { tag *chunk.Tag // tag for the chunk sentAt time.Time // most recently sent at time synced bool // set when chunk got synced + + // roundtrip span + sp opentracing.Span } // NewPusher contructs a Pusher and starts up the push sync protocol @@ -64,13 +72,14 @@ type pushedItem struct { // - a DB interface to subscribe to push sync index to allow iterating over recently stored chunks // - a pubsub interface to send chunks and receive statements of custody // - tags that hold the several tag -func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { +func NewPusher(store DB, ps PubSub, tags *chunk.Tags, nnf func(storage.Address) bool) *Pusher { p := &Pusher{ + nnf: nnf, store: store, tags: tags, quit: make(chan struct{}), pushed: make(map[string]*pushedItem), - receipts: make(chan chunk.Address), + receipts: make(chan *receiptMsg), ps: ps, } go p.sync() @@ -149,50 +158,72 @@ func (p *Pusher) sync() { // handle incoming chunks case ch, more := <-chunks: - chunksInBatch++ - // if no more, set to nil and wait for timer - if !more { - chunks = nil - continue - } + func() { + chunksInBatch++ + // if no more, set to nil and wait for timer + if !more { + chunks = nil + return + } - metrics.GetOrRegisterCounter("pusher.send-chunk", nil).Inc(1) - // if no need to sync this chunk then continue - if !p.needToSync(ch) { - continue - } + metrics.GetOrRegisterCounter("pusher.send-chunk", nil).Inc(1) + // if no need to sync this chunk then continue + if !p.needToSync(ch) { + return + } - metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) - // send the chunk and ignore the error - if err := p.sendChunkMsg(ch); err != nil { - log.Error("error sending chunk", "addr", ch.Address(), "err", err) - } + metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) + // send the chunk and ignore the error + go func(ch chunk.Chunk) { + if err := p.sendChunkMsg(ch); err != nil { + log.Error("error sending chunk", "addr", ch.Address(), "err", err) + } + }(ch) + }() // handle incoming receipts - case addr := <-p.receipts: - metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) - log.Debug("synced", "addr", addr) - // ignore if already received receipt - item, found := p.pushed[addr.Hex()] - if !found { - metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) - log.Debug("not wanted or already got... ignore", "addr", addr) - continue - } - if item.synced { - metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) - log.Debug("just synced... ignore", "addr", addr) - continue - } - metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) - // collect synced addresses - synced = append(synced, addr) - // set synced flag - item.synced = true - // increment synced count for the tag if exists - if item.tag != nil { - item.tag.Inc(chunk.StateSynced) - } + case rec := <-p.receipts: + addr := chunk.Address(rec.Addr) + origin := rec.Origin + func() { + metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) + log.Debug("synced", "addr", addr) + // ignore if already received receipt + item, found := p.pushed[addr.Hex()] + if !found { + metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) + log.Debug("not wanted or already got... ignore", "addr", addr) + return + } + if item.synced { + metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) + log.Debug("just synced... ignore", "addr", addr) + return + } + + timediff := time.Since(item.sentAt) + log.Debug("time to sync", "dur", timediff) + + metrics.GetOrRegisterResettingTimer("pusher.chunk.roundtrip", nil).Update(timediff) + + metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) + // collect synced addresses + synced = append(synced, addr) + // set synced flag + item.synced = true + // increment synced count for the tag if exists + if item.tag != nil { + item.tag.Inc(chunk.StateSynced) + + item.sp.LogFields(olog.String("ro", fmt.Sprintf("%x", origin))) + item.sp.Finish() + + if item.tag.DoneSyncing() { + log.Info("closing root span for tag", "taguid", item.tag.Uid, "tagname", item.tag.Name) + item.tag.FinishRootSpan() + } + } + }() case <-p.quit: // if there was a subscription, cancel it @@ -213,15 +244,20 @@ func (p *Pusher) handleReceiptMsg(msg []byte) error { return err } log.Debug("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) - p.PushReceipt(receipt.Addr) + p.pushReceipt(receipt.Addr, receipt.Origin) return nil } // pushReceipt just inserts the address into the channel // it is also called by the push sync Storer if the originator and storer identical -func (p *Pusher) PushReceipt(addr []byte) { +func (p *Pusher) pushReceipt(addr []byte, origin []byte) { + r := &receiptMsg{ + addr, + origin, + []byte{}, + } select { - case p.receipts <- addr: + case p.receipts <- r: case <-p.quit: } } @@ -229,6 +265,8 @@ func (p *Pusher) PushReceipt(addr []byte) { // sendChunkMsg sends chunks to their destination // using the PubSub interface Send method (e.g., pss neighbourhood addressing) func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { + rlpTimer := time.Now() + cmsg := &chunkMsg{ Origin: p.ps.BaseAddr(), Addr: ch.Address()[:], @@ -240,6 +278,10 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { return err } log.Debug("send chunk", "addr", label(ch.Address()), "self", label(p.ps.BaseAddr())) + + metrics.GetOrRegisterResettingTimer("pusher.send.chunk.rlp", nil).UpdateSince(rlpTimer) + + defer metrics.GetOrRegisterResettingTimer("pusher.send.chunk.pss", nil).UpdateSince(time.Now()) return p.ps.Send(ch.Address()[:], pssChunkTopic, msg) } @@ -260,15 +302,63 @@ func (p *Pusher) needToSync(ch chunk.Chunk) bool { } // first time encountered } else { + + addr := ch.Address() + // remember item tag, _ := p.tags.Get(ch.TagID()) item = &pushedItem{ tag: tag, } + + // should i sync?? + if !p.nnf(addr) { + // no => + + // mark as synced + // set chunk status to synced, insert to db GC index + if err := p.store.Set(context.Background(), chunk.ModeSetSync, addr); err != nil { + log.Warn("error setting chunk to synced", "addr", addr, "err", err) + } + + // set synced flag + item.synced = true + // increment synced count for the tag if exists + if item.tag != nil { + item.tag.Inc(chunk.StateSynced) + + // opentracing for self chunks that don't need syncing? + _, osp := spancontext.StartSpan( + tag.Tctx, + "chunk.mine") + osp.LogFields(olog.String("ref", ch.Address().String())) + osp.SetTag("addr", ch.Address().String()) + osp.Finish() + + if item.tag.DoneSyncing() { + log.Info("closing root span for tag", "taguid", item.tag.Uid, "tagname", item.tag.Name) + item.tag.FinishRootSpan() + } + } + + return false + } + // i should sync + // increment SENT count on tag if it exists - if item.tag != nil { - item.tag.Inc(chunk.StateSent) + if tag != nil { + tag.Inc(chunk.StateSent) + + // opentracing for chunk roundtrip + _, osp := spancontext.StartSpan( + tag.Tctx, + "chunk.sent") + osp.LogFields(olog.String("ref", ch.Address().String())) + osp.SetTag("addr", ch.Address().String()) + + item.sp = osp } + // remember the item p.pushed[ch.Address().Hex()] = item } diff --git a/storage/pushsync/pusher_test.go b/storage/pushsync/pusher_test.go index 743cb1db92..7bd7db169e 100644 --- a/storage/pushsync/pusher_test.go +++ b/storage/pushsync/pusher_test.go @@ -32,6 +32,7 @@ import ( "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/network" "github.com/ethersphere/swarm/storage" colorable "github.com/mattn/go-colorable" ) @@ -196,6 +197,7 @@ func delayResponse() bool { // - already synced chunks are not resynced // - if no more data inserted, the db is emptied shortly func TestPusher(t *testing.T) { + timeout := 10 * time.Second chunkCnt := 200 tagCnt := 4 @@ -275,7 +277,8 @@ func TestPusher(t *testing.T) { // construct the mock push sync index iterator tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) // start push syncing in a go routine - p := NewPusher(tp, ps, tags) + kad := network.NewKademlia(nil, network.NewKadParams()) + p := NewPusher(tp, ps, tags, kad) defer p.Close() // collect synced chunks until all chunks synced // wait on errc for errors on any thread @@ -378,14 +381,16 @@ func TestPushSyncAndStoreWithLoopbackPubSub(t *testing.T) { tags, tagIDs := setupTags(chunkCnt, tagCnt) // construct the mock push sync index iterator tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) + // neighbourhood function mocked + nnf := func(storage.Address) bool { return true } // start push syncing in a go routine - p := NewPusher(tp, ps, tags) + p := NewPusher(tp, ps, tags, nnf) defer p.Close() // set up a number of storers storers := make([]*Storer, storerCnt) for i := 0; i < storerCnt; i++ { - storers[i] = NewStorer(&testStore{store}, ps, p.PushReceipt) + storers[i] = NewStorer(&testStore{store}, ps, nnf, p.pushReceipt) } synced := 0 diff --git a/storage/pushsync/pushsync_simulation_test.go b/storage/pushsync/pushsync_simulation_test.go index c6119f2ac2..70271724d7 100644 --- a/storage/pushsync/pushsync_simulation_test.go +++ b/storage/pushsync/pushsync_simulation_test.go @@ -56,18 +56,18 @@ var ( // * downloader downloads the chunk // Trials are run concurrently func TestPushSyncSimulation(t *testing.T) { - nodeCnt := 4 + nodeCnt := 16 chunkCnt := 500 - trials := 10 - err := testSyncerWithPubSub(t, nodeCnt, chunkCnt, trials, newServiceFunc) + testcases := 10 + err := testSyncerWithPubSub(t, nodeCnt, chunkCnt, testcases, newServiceFunc) if err != nil { t.Fatal(err) } } -func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, trials int, sf simulation.ServiceFunc) error { +func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, testcases int, sf simulation.ServiceFunc) error { t.Helper() - sim := simulation.New(map[string]simulation.ServiceFunc{ + sim := simulation.NewInProc(map[string]simulation.ServiceFunc{ "streamer": sf, }) defer sim.Close() @@ -78,12 +78,13 @@ func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, trials int, sf simula if err != nil { t.Fatal(err) } + log.Info("Snapshot loaded") time.Sleep(2 * time.Second) result := sim.Run(ctx, func(ctx context.Context, sim *simulation.Simulation) error { time.Sleep(2 * time.Second) errc := make(chan error) - for i := 0; i < trials; i++ { + for i := 0; i < testcases; i++ { go uploadAndDownload(ctx, sim, errc, nodeCnt, chunkCnt, i) } i := 0 @@ -92,7 +93,7 @@ func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, trials int, sf simula return err } i++ - if i >= trials { + if i >= testcases { break } } @@ -138,11 +139,7 @@ func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, errc cha } // wait till synced - for { - n, total, err := tag.Status(chunk.StateSynced) - if err == nil && n == total { - break - } + for !tag.DoneSyncing() { time.Sleep(100 * time.Millisecond) } @@ -181,8 +178,8 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic bucket.Store(simulation.BucketKeyKademlia, kad) privKey, err := crypto.GenerateKey() - pssp := pss.NewPssParams().WithPrivateKey(privKey) - ps, err := pss.NewPss(kad, pssp) + pssp := pss.NewParams().WithPrivateKey(privKey) + ps, err := pss.New(kad, pssp) if err != nil { return nil, nil, err } @@ -199,11 +196,11 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic pubSub := pss.NewPubSub(ps) // set up syncer - p := NewPusher(lstore, pubSub, chunk.NewTags()) + p := NewPusher(lstore, pubSub, chunk.NewTags(), kad) bucket.Store(bucketKeyPushSyncer, p) // setup storer - s := NewStorer(netStore, pubSub, p.PushReceipt) + s := NewStorer(netStore, pubSub, kad, p.pushReceipt) cleanup := func() { p.Close() @@ -243,7 +240,7 @@ func (s *StreamerAndPss) Stop() error { } func upload(ctx context.Context, store Store, tags *chunk.Tags, tagname string, n int) (tag *chunk.Tag, addrs []storage.Address, err error) { - tag, err = tags.New(tagname, int64(n)) + tag, err = tags.Create(tagname, int64(n)) if err != nil { return nil, nil, err } diff --git a/storage/pushsync/storer.go b/storage/pushsync/storer.go index c0a966ac8b..be2159bded 100644 --- a/storage/pushsync/storer.go +++ b/storage/pushsync/storer.go @@ -26,7 +26,10 @@ import ( "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" + "github.com/ethersphere/swarm/network" + "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" + olog "github.com/opentracing/opentracing-go/log" ) // Store is the storage interface to save chunks @@ -37,10 +40,11 @@ type Store interface { // Storer is the object used by the push-sync server side protocol type Storer struct { - store Store // store to put chunks in, and retrieve them - ps PubSub // pubsub interface to receive chunks and send receipts - deregister func() // deregister the registered handler when Storer is closed - pushReceipt func(addr []byte) // to be called... + kad *network.Kademlia + store Store // store to put chunks in, and retrieve them + ps PubSub // pubsub interface to receive chunks and send receipts + deregister func() // deregister the registered handler when Storer is closed + pushReceipt func(addr []byte, origin []byte) // to be called... } // NewStorer constructs a Storer @@ -50,8 +54,9 @@ type Storer struct { // - the chunks are stored and synced to their nearest neighbours and // - a statement of custody receipt is sent as a response to the originator // it sets a cancel function that deregisters the handler -func NewStorer(store Store, ps PubSub, pushReceipt func(addr []byte)) *Storer { +func NewStorer(store Store, ps PubSub, kad *network.Kademlia, pushReceipt func(addr []byte, origin []byte)) *Storer { s := &Storer{ + kad: kad, store: store, ps: ps, pushReceipt: pushReceipt, @@ -75,6 +80,13 @@ func (s *Storer) handleChunkMsg(msg []byte) error { if err != nil { return err } + + _, osp := spancontext.StartSpan( + context.TODO(), + "handle.chunk.msg") + defer osp.Finish() + osp.LogFields(olog.String("ref", fmt.Sprintf("%x", chmsg.Addr))) + osp.SetTag("addr", fmt.Sprintf("%x", chmsg.Addr)) log.Debug("Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin), "self", fmt.Sprintf("%x", s.ps.BaseAddr())) return s.processChunkMsg(chmsg) } @@ -91,7 +103,15 @@ func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { if _, err := s.store.Put(context.TODO(), chunk.ModePutSync, ch); err != nil { return err } - log.Debug("push sync storer", "addr", label(chmsg.Addr), "to", label(chmsg.Origin), "self", hex.EncodeToString(s.ps.BaseAddr())) + + closerPeer := s.kad.CloserPeerThanMeXOR(chmsg.Addr) + + log.Trace("closer than me", "ref", fmt.Sprintf("%x", chmsg.Addr), "res", closerPeer) + // if there is closer peer, do not send back a receipt + if closerPeer { + return nil + } + // TODO: check if originator or relayer is a nearest neighbour then return // otherwise send back receipt return s.sendReceiptMsg(chmsg) @@ -101,20 +121,32 @@ func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { // to the originator of a push-synced chunk message. // Including a unique nonce makes the receipt immune to deduplication cache func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { + _, osp := spancontext.StartSpan( + context.TODO(), + "send.receipt") + defer osp.Finish() + osp.LogFields(olog.String("ref", fmt.Sprintf("%x", chmsg.Addr))) + osp.SetTag("addr", fmt.Sprintf("%x", chmsg.Addr)) + // if origin is self, use direct channel, no pubsub send needed if bytes.Equal(chmsg.Origin, s.ps.BaseAddr()) { - go s.pushReceipt(chmsg.Addr) + osp.LogFields(olog.String("origin", "self")) + + go s.pushReceipt(chmsg.Addr, chmsg.Origin) return nil } + osp.LogFields(olog.String("origin", fmt.Sprintf("%x", chmsg.Origin))) + rmsg := &receiptMsg{ - Addr: chmsg.Addr, - Nonce: newNonce(), + Addr: chmsg.Addr, + Origin: s.ps.BaseAddr(), // receipt origin is who is sending back the receipt + Nonce: newNonce(), } msg, err := rlp.EncodeToBytes(rmsg) if err != nil { return err } to := chmsg.Origin - log.Debug("send receipt", "addr", label(chmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) + log.Debug("send receipt", "addr", label(rmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) return s.ps.Send(to, pssReceiptTopic, msg) } diff --git a/swarm.go b/swarm.go index 60505d1246..323d71c1c8 100644 --- a/swarm.go +++ b/swarm.go @@ -246,7 +246,7 @@ func NewSwarm(config *api.Config, mockStore *mock.NodeStore) (self *Swarm, err e pubsub := pss.NewPubSub(self.ps) self.pushSync = pushsync.NewPusher(localStore, pubsub, tags) - self.storer = pushsync.NewStorer(localStore, pubsub) + self.storer = pushsync.NewStorer(self.netStore, pubsub) self.api = api.NewAPI(self.fileStore, self.dns, feedsHandler, self.privateKey, tags) From 8cb5558d805e6f3b053c55034dd30e70ccf78ae7 Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:27:37 +0200 Subject: [PATCH 07/22] chunk: tags improvement - WaitTillDone does check initially - introduce IncN to increment with n - api: inspector to use tag.Done - unexport context, span, and Context() to be used by http server --- api/http/server.go | 2 +- api/inspector.go | 3 ++- chunk/tag.go | 57 +++++++++++++++++++++++++++++++++------------- chunk/tags.go | 2 +- 4 files changed, 45 insertions(+), 19 deletions(-) diff --git a/api/http/server.go b/api/http/server.go index 1a506cf34b..028034ac01 100644 --- a/api/http/server.go +++ b/api/http/server.go @@ -360,7 +360,7 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { ctx := r.Context() - _, sp := spancontext.StartSpan(tag.Tctx, "http.post") + _, sp := spancontext.StartSpan(tag.Context(), "http.post") defer sp.Finish() contentType, params, err := mime.ParseMediaType(r.Header.Get("Content-Type")) diff --git a/api/inspector.go b/api/inspector.go index 88d5249557..1bdd912706 100644 --- a/api/inspector.go +++ b/api/inspector.go @@ -24,6 +24,7 @@ import ( "time" "github.com/ethereum/go-ethereum/metrics" + "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/network" stream "github.com/ethersphere/swarm/network/stream/v2" @@ -59,7 +60,7 @@ func (i *Inspector) IsPushSynced(tagname string) bool { for _, t := range tags { if t.Name == tagname { - ds := t.DoneSyncing() + ds := t.Done(chunk.StateSynced) log.Debug("found tag", "tagname", tagname, "done-syncing", ds) diff --git a/chunk/tag.go b/chunk/tag.go index 1d0be8bee6..507e05118a 100644 --- a/chunk/tag.go +++ b/chunk/tag.go @@ -59,8 +59,8 @@ type Tag struct { StartedAt time.Time // tag started to calculate ETA // end-to-end tag tracing - Tctx context.Context // tracing context - Span opentracing.Span // tracing root span TODO: should it be exported? + ctx context.Context // tracing context + span opentracing.Span // tracing root span } // New creates a new tag, stores it by the name and returns it @@ -73,16 +73,22 @@ func NewTag(uid uint32, s string, total int64) *Tag { Total: total, } - t.Tctx, t.Span = spancontext.StartSpan(context.Background(), "new.upload.tag") + t.ctx, t.span = spancontext.StartSpan(context.Background(), "new.upload.tag") return t } +// Context accessor +func (t *Tag) Context() context.Context { + return t.ctx +} + +// FinishRootSpan closes the pushsync span of the tags func (t *Tag) FinishRootSpan() { - t.Span.Finish() + t.span.Finish() } -// Inc increments the count for a state -func (t *Tag) Inc(state State) { +// IncN increments the count for a state +func (t *Tag) IncN(state State, n int) { var v *int64 switch state { case StateSplit: @@ -96,7 +102,12 @@ func (t *Tag) Inc(state State) { case StateSynced: v = &t.Synced } - atomic.AddInt64(v, 1) + atomic.AddInt64(v, int64(n)) +} + +// Inc increments the count for a state +func (t *Tag) Inc(state State) { + t.IncN(state, 1) } // Get returns the count for a state on a tag @@ -122,14 +133,30 @@ func (t *Tag) TotalCounter() int64 { return atomic.LoadInt64(&t.Total) } -func (t *Tag) DoneSyncing() bool { - n, total, err := t.Status(StateSynced) - - if err == nil && n == total { - return true +// WaitTillDone returns without error once the tag is complete +// wrt the state given as argument +// it returns an error if the context is done +func (t *Tag) WaitTillDone(ctx context.Context, s State) error { + if t.Done(s) { + return nil + } + ticker := time.NewTicker(100 * time.Millisecond) + for { + select { + case <-ticker.C: + if t.Done(s) { + return nil + } + case <-ctx.Done(): + return ctx.Err() + } } +} - return false +// Done returns true if tag is complete wrt the state given as argument +func (t *Tag) Done(s State) bool { + n, total, err := t.Status(s) + return err == nil && n == total } // DoneSplit sets total count to SPLIT count and sets the associated swarm hash for this tag @@ -192,9 +219,7 @@ func (tag *Tag) MarshalBinary() (data []byte, err error) { n = binary.PutVarint(intBuffer, int64(len(tag.Address))) buffer = append(buffer, intBuffer[:n]...) - - buffer = append(buffer, tag.Address...) - + buffer = append(buffer, tag.Address[:]...) buffer = append(buffer, []byte(tag.Name)...) return buffer, nil diff --git a/chunk/tags.go b/chunk/tags.go index 4df6500d8f..c3ca4ab939 100644 --- a/chunk/tags.go +++ b/chunk/tags.go @@ -53,7 +53,7 @@ func (ts *Tags) Create(s string, total int64) (*Tag, error) { return nil, errExists } - t.Tctx, t.Span = spancontext.StartSpan(context.Background(), "new.upload.tag") + t.ctx, t.span = spancontext.StartSpan(context.Background(), "new.upload.tag") return t, nil } From dc0c9730956308ab111be56dd6788c3df2f28820 Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:28:37 +0200 Subject: [PATCH 08/22] shed: linting fix --- shed/index.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/shed/index.go b/shed/index.go index 849a466396..8dbb74bb1e 100644 --- a/shed/index.go +++ b/shed/index.go @@ -101,7 +101,7 @@ type IndexFuncs struct { // NewIndex returns a new Index instance with defined name and // encoding functions. The name must be unique and will be validated // on database schema for a key prefix byte. -func (db *DB) NewIndex(name string, funcs IndexFuncs) (f Index, err error) { +func (db *DB) NewIndex(name string, funcs IndexFuncs) (f Index, err error) { id, err := db.schemaIndexPrefix(name) if err != nil { return f, err From 6a7e94b9ef840b1d029d5a5c1c07f85a8a341394 Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:29:58 +0200 Subject: [PATCH 09/22] pot: DistanceCmp opposite of ProxCmp reflecting doc --- pot/address.go | 2 +- pot/address_test.go | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/pot/address.go b/pot/address.go index d7bed6c46e..cc88c35d37 100644 --- a/pot/address.go +++ b/pot/address.go @@ -114,7 +114,7 @@ func DistanceCmp(a, x, y []byte) (int, error) { if len(a) != len(x) || len(a) != len(y) { return 0, errors.New("address length must match") } - return ProxCmp(a, x, y), nil + return ProxCmp(a, y, x), nil } // ProxCmp compares the distances x->a and y->a diff --git a/pot/address_test.go b/pot/address_test.go index 3c914fe84c..f33e374325 100644 --- a/pot/address_test.go +++ b/pot/address_test.go @@ -34,13 +34,13 @@ var ( x: hexutil.MustDecode("0x9100000000000000000000000000000000000000000000000000000000000000"), y: hexutil.MustDecode("0x8200000000000000000000000000000000000000000000000000000000000000"), z: hexutil.MustDecode("0x1200000000000000000000000000000000000000000000000000000000000000"), - result: -1, + result: 1, }, { x: hexutil.MustDecode("0x9100000000000000000000000000000000000000000000000000000000000000"), y: hexutil.MustDecode("0x1200000000000000000000000000000000000000000000000000000000000000"), z: hexutil.MustDecode("0x8200000000000000000000000000000000000000000000000000000000000000"), - result: 1, + result: -1, }, { x: hexutil.MustDecode("0x9100000000000000000000000000000000000000000000000000000000000000"), From 9e6f990059eb1dc3076cf7a402ee1e882a3cc2af Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:30:43 +0200 Subject: [PATCH 10/22] network: add IsClosestTo(addr, filter) using pot.DistanceCmp --- network/kademlia.go | 54 ++++++++++++++------------------------------- 1 file changed, 17 insertions(+), 37 deletions(-) diff --git a/network/kademlia.go b/network/kademlia.go index f8566b407c..94b2ce47c2 100644 --- a/network/kademlia.go +++ b/network/kademlia.go @@ -569,51 +569,31 @@ func (k *Kademlia) callable(e *entry) bool { return true } -func (k *Kademlia) CloserPeerThanMeXOR(addr []byte) bool { - var ret bool - - myDistance := make([]byte, 32) - chunk.XOR(myDistance, k.BaseAddr(), addr) - +// IsClosestTo returns true if self is the closest peer to addr among filtered peers +// ie. return false iff there is a peer that +// - filter(bzzpeer) == true AND +// - pot.DistanceCmp(addr, peeraddress, selfaddress) == 1 +func (k *Kademlia) IsClosestTo(addr []byte, filter func(*BzzPeer) bool) (closest bool) { + myPo := chunk.Proximity(addr, k.BaseAddr()) // iterate connection in kademlia + closest = true k.EachConn(addr, 255, func(p *Peer, po int) bool { - if !p.BzzPeer.Peer.HasCap("pss") { + if !filter(p.BzzPeer) { return true } - - otherDistance := make([]byte, 32) - chunk.XOR(otherDistance, p.Over(), addr) - - if bytes.Compare(myDistance, otherDistance) == 1 { - ret = true + if po != myPo { + closest = po < myPo return false } - - return true - }) - - return ret -} - -func (k *Kademlia) CloserPeerThanMe(addr []byte) bool { - var ret bool - - myPo, _ := Pof(k.BaseAddr(), addr, 0) - - // iterate connection in kademlia - k.EachConn(addr, 255, func(p *Peer, po int) bool { - if !p.BzzPeer.Peer.HasCap("pss") { - return true - } - - if po > myPo { - ret = true + // if proximity order of closest PO nodes equal our own, + // then use XOR-based DistanceCmp and return if self is not closest + if d, _ := pot.DistanceCmp(addr, p.Over(), k.BaseAddr()); d == 1 { + closest = false + return false } - - return false + return true }) - - return ret + return closest } // BaseAddr return the kademlia base address From 61ca500464f4cf6162225692cd44fb28112e989b Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:31:51 +0200 Subject: [PATCH 11/22] pss: fix hashpool init to use keccak256 - minor improvements in logging - calls on Kademlia directly on Pss struct - add IsClosestTo function to pubsub using kademlia.IsClosestTo --- pss/pss.go | 32 +++++++++++++++++++------------- pss/pubsub.go | 18 ++++++++++++++++-- 2 files changed, 35 insertions(+), 15 deletions(-) diff --git a/pss/pss.go b/pss/pss.go index 0c8d4eb11c..2c6df9e838 100644 --- a/pss/pss.go +++ b/pss/pss.go @@ -37,7 +37,6 @@ import ( "github.com/ethersphere/swarm/p2p/protocols" "github.com/ethersphere/swarm/pot" "github.com/ethersphere/swarm/pss/crypto" - "github.com/ethersphere/swarm/storage" "golang.org/x/crypto/sha3" ) @@ -269,7 +268,7 @@ func New(k *network.Kademlia, params *Params) (*Pss, error) { ps.outbox = newOutbox(defaultOutboxCapacity, ps.quitC, ps.forward) for i := 0; i < hasherCount; i++ { - hashfunc := storage.MakeHashFunc(storage.DefaultHash)() + hashfunc := sha3.NewLegacyKeccak256() ps.hashPool.Put(hashfunc) } @@ -484,9 +483,9 @@ func (p *Pss) handle(ctx context.Context, msg interface{}) error { // raw is simplest handler contingency to check, so check that first var isRaw bool if pssmsg.isRaw() { - if capabilities, ok := p.getTopicHandlerCaps(psstopic); ok { + if capabilities, ok := p.getTopicHandlerCaps(Topic(psstopic)); ok { if !capabilities.raw { - log.Debug("No handler for raw message", "topic", psstopic) + log.Debug("No handler for raw message", "topic", label(psstopic[:])) return nil } } @@ -498,7 +497,7 @@ func (p *Pss) handle(ctx context.Context, msg interface{}) error { // - prox handler on message and we are in prox regardless of partial address match // store this result so we don't calculate again on every handler var isProx bool - if capabilities, ok := p.getTopicHandlerCaps(psstopic); ok { + if capabilities, ok := p.getTopicHandlerCaps(Topic(psstopic)); ok { isProx = capabilities.prox } isRecipient := p.isSelfPossibleRecipient(pssmsg, isProx) @@ -569,7 +568,7 @@ func (p *Pss) executeHandlers(topic Topic, payload []byte, from PssAddress, raw defer metrics.GetOrRegisterResettingTimer("pss.execute-handlers", nil).UpdateSince(time.Now()) handlers := p.getHandlers(topic) - peer := p2p.NewPeer(enode.ID{}, fmt.Sprintf("%x", from), []p2p.Cap{}) + peer := p2p.NewPeer(enode.ID{}, hex.EncodeToString(from), []p2p.Cap{}) for _, h := range handlers { if !h.caps.raw && raw { log.Warn("norawhandler") @@ -593,7 +592,7 @@ func (p *Pss) isSelfRecipient(msg *PssMsg) bool { // test match of leftmost bytes in given message to node's Kademlia address func (p *Pss) isSelfPossibleRecipient(msg *PssMsg, prox bool) bool { - local := p.Kademlia.BaseAddr() + local := p.BaseAddr() // if a partial address matches we are possible recipient regardless of prox // if not and prox is not set, we are surely not @@ -604,7 +603,7 @@ func (p *Pss) isSelfPossibleRecipient(msg *PssMsg, prox bool) bool { return false } - depth := p.Kademlia.NeighbourhoodDepth() + depth := p.NeighbourhoodDepth() po, _ := network.Pof(p.Kademlia.BaseAddr(), msg.To, 0) log.Trace("selfpossible", "po", po, "depth", depth) @@ -734,7 +733,7 @@ func sendMsg(p *Pss, sp *network.Peer, msg *PssMsg) bool { } } if !isPssEnabled { - log.Warn("peer doesn't have matching pss capabilities, skipping", "peer", info.Name, "caps", info.Caps, "peer", fmt.Sprintf("%x", sp.BzzAddr.Address())) + log.Warn("peer doesn't have matching pss capabilities, skipping", "peer", info.Name, "caps", info.Caps, "peer", label(sp.BzzAddr.Address())) return false } @@ -769,7 +768,7 @@ func (p *Pss) forward(msg *PssMsg) error { sent := 0 // number of successful sends to := make([]byte, addressLength) copy(to[:len(msg.To)], msg.To) - neighbourhoodDepth := p.Kademlia.NeighbourhoodDepth() + neighbourhoodDepth := p.NeighbourhoodDepth() // luminosity is the opposite of darkness. the more bytes are removed from the address, the higher is darkness, // but the luminosity is less. here luminosity equals the number of bits given in the destination address. @@ -794,7 +793,7 @@ func (p *Pss) forward(msg *PssMsg) error { onlySendOnce = true } - p.Kademlia.EachConn(to, addressLength*8, func(sp *network.Peer, po int) bool { + p.EachConn(to, addressLength*8, func(sp *network.Peer, po int) bool { if po < broadcastThreshold && sent > 0 { return false // stop iterating } @@ -838,7 +837,14 @@ func (p *Pss) cleanFwdCache() { } func label(b []byte) string { - return fmt.Sprintf("%04x", b[:2]) + if len(b) == 0 { + return "-" + } + l := 2 + if len(b) == 1 { + l = 1 + } + return fmt.Sprintf("%04x", b[:l]) } // add a message to the cache @@ -869,7 +875,7 @@ func (p *Pss) checkFwdCache(msg *PssMsg) bool { entry, ok := p.fwdCache[digest] if ok { if entry.expiresAt.After(time.Now()) { - log.Trace("unexpired cache", "digest", fmt.Sprintf("%x", digest)) + log.Trace("unexpired cache", "self", label(p.BaseAddr()), "digest", label(digest[:]), "to", label(msg.To)) metrics.GetOrRegisterCounter("pss.checkfwdcache.unexpired", nil).Inc(1) return true } diff --git a/pss/pubsub.go b/pss/pubsub.go index 03ebf9ee5f..decb4819f5 100644 --- a/pss/pubsub.go +++ b/pss/pubsub.go @@ -16,7 +16,10 @@ package pss -import "github.com/ethereum/go-ethereum/p2p" +import ( + "github.com/ethereum/go-ethereum/p2p" + "github.com/ethersphere/swarm/network" +) // PubSub implements the pushsync.PubSub interface using pss type PubSub struct { @@ -32,7 +35,18 @@ func NewPubSub(p *Pss) *PubSub { // BaseAddr returns Kademlia base address func (p *PubSub) BaseAddr() []byte { - return p.pss.Kademlia.BaseAddr() + return p.pss.BaseAddr() +} + +func isPssPeer(bp *network.BzzPeer) bool { + return bp.HasCap(protocolName) +} + +// IsClosestTo returns true is self is the closest known node to addr +// as uniquely defined by the MSB XOR distance +// among pss capable peers +func (p *PubSub) IsClosestTo(addr []byte) bool { + return p.pss.IsClosestTo(addr, isPssPeer) } // Register registers a handler From 32e04ae68671283c9873db5388c0a04fdbe8a48a Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 27 Aug 2019 12:32:21 +0200 Subject: [PATCH 12/22] pushsync, swarm.go: complete protocol - all tests pass non-flaky - move package from storage to toplevel - only closest peer to address returns a receipt - IsClosestTo(addr) is now part of the PubSub interface - rename TestPushSyncAndStoreWithLoopback to TestProtocol - for TestPusher and , IsClosest is mocked properly - remove Origin field from receipt message - pushed item remembers first and last sent time - retryInterval is dynamically set as 2 * average roundtrip (excluding outliers) - early send check is removed from unit test - receipts channel is just []byte for address - we are using mutli-set for setting synced status on chunks - tag increment now follows multiset and not incorrectly when the receipt arrives for this remember syncedItems is needed alongside syncedAddrs - in pusher sync loop, we use static context - correctly unsubscribe DB.SubscribePush - if pusher is closest node to a chunk, chunk is not sent using pubsub, but receipt is directly sent to self using a shortcut - therefore no self send is needed in storer - loopBack pubsub is shared in the protocol unit test but wrapped in different testPubSub structs to control the behaviour of IsClosestTo function - added delayResponse to TestProtocol too - testPushSyncIndex SubscribePush now increments tag StateStored correctly only first time - fix checkTags to wait for synced status (it caused occasional flakiness) - extract simulation test parameters (nodes/chunks/testcases) as command line flags, default is 16/16/16 --- {storage/pushsync => pushsync}/protocol.go | 6 +- pushsync/protocol_test.go | 96 ++++++ {storage/pushsync => pushsync}/pusher.go | 292 ++++++++---------- {storage/pushsync => pushsync}/pusher_test.go | 208 +++++-------- .../simulation_test.go | 104 ++++--- {storage/pushsync => pushsync}/storer.go | 61 ++-- swarm.go | 6 +- 7 files changed, 385 insertions(+), 388 deletions(-) rename {storage/pushsync => pushsync}/protocol.go (94%) create mode 100644 pushsync/protocol_test.go rename {storage/pushsync => pushsync}/pusher.go (53%) rename {storage/pushsync => pushsync}/pusher_test.go (63%) rename storage/pushsync/pushsync_simulation_test.go => pushsync/simulation_test.go (75%) rename {storage/pushsync => pushsync}/storer.go (66%) diff --git a/storage/pushsync/protocol.go b/pushsync/protocol.go similarity index 94% rename from storage/pushsync/protocol.go rename to pushsync/protocol.go index 6476d422e2..093e5d36ac 100644 --- a/storage/pushsync/protocol.go +++ b/pushsync/protocol.go @@ -34,6 +34,7 @@ type PubSub interface { Register(topic string, prox bool, handler func(msg []byte, p *p2p.Peer) error) func() Send(to []byte, topic string, msg []byte) error BaseAddr() []byte + IsClosestTo([]byte) bool } // chunkMsg is the message construct to send chunks to their local neighbourhood @@ -48,9 +49,8 @@ type chunkMsg struct { // it is currently a notification only (contains no proof) sent to the originator // Nonce is there to make multiple responses immune to deduplication cache type receiptMsg struct { - Addr []byte - Origin []byte - Nonce []byte + Addr []byte // chunk address + Nonce []byte // nonce to make multiple instances of send immune to deduplication cache } func decodeChunkMsg(msg []byte) (*chunkMsg, error) { diff --git a/pushsync/protocol_test.go b/pushsync/protocol_test.go new file mode 100644 index 0000000000..82746b085d --- /dev/null +++ b/pushsync/protocol_test.go @@ -0,0 +1,96 @@ +package pushsync + +import ( + "context" + "encoding/binary" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/ethersphere/swarm/chunk" + "github.com/ethersphere/swarm/log" +) + +type testStore struct { + store *sync.Map +} + +func (t *testStore) Put(_ context.Context, _ chunk.ModePut, chs ...chunk.Chunk) ([]bool, error) { + exists := make([]bool, len(chs)) + for i, ch := range chs { + idx := binary.BigEndian.Uint64(ch.Address()[:8]) + var storedCnt uint32 = 1 + if v, loaded := t.store.LoadOrStore(idx, &storedCnt); loaded { + atomic.AddUint32(v.(*uint32), 1) + exists[i] = loaded + } + log.Debug("testStore put", "idx", idx) + } + return exists, nil +} + +// TestProtocol tests the push sync protocol +// push syncer node communicate with storers via mock loopback PubSub +func TestProtocol(t *testing.T) { + timeout := 10 * time.Second + chunkCnt := 1024 + tagCnt := 4 + storerCnt := 4 + + sent := &sync.Map{} + store := &sync.Map{} + // mock pubsub messenger + lb := newLoopBack(true) + + // set up a number of storers + storers := make([]*Storer, storerCnt) + for i := 0; i < storerCnt; i++ { + // every chunk is closest to exactly one storer + j := i + isClosestTo := func(addr []byte) bool { + n := int(binary.BigEndian.Uint64(addr[:8])) + log.Debug("closest node?", "n", n, "n%storerCnt", n%storerCnt, "storer", j) + return n%storerCnt == j + } + storers[j] = NewStorer(&testStore{store}, &testPubSub{lb, isClosestTo}) + } + + tags, tagIDs := setupTags(chunkCnt, tagCnt) + // construct the mock push sync index iterator + tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) + // isClosestTo function mocked + isClosestTo := func([]byte) bool { return false } + // start push syncing in a go routine + p := NewPusher(tp, &testPubSub{lb, isClosestTo}, tags) + defer p.Close() + + synced := make(map[int]int) + for { + select { + case idx := <-tp.synced: + n := synced[idx] + synced[idx] = n + 1 + if len(synced) == chunkCnt { + expTotal := chunkCnt / tagCnt + checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) + for i := uint64(0); i < uint64(chunkCnt); i++ { + if n := synced[int(i)]; n != 1 { + t.Fatalf("expected to receive exactly 1 receipt for chunk %v, got %v", i, n) + } + v, ok := store.Load(i) + if !ok { + t.Fatalf("chunk %v not stored", i) + } + _ = v + // if cnt := *(v.(*uint32)); cnt < uint32(storerCnt) { + // t.Fatalf("chunk %v expected to be saved at least %v times, got %v", i, storerCnt, cnt) + // } + } + return + } + case <-time.After(timeout): + t.Fatalf("timeout waiting for all chunks to be synced") + } + } +} diff --git a/storage/pushsync/pusher.go b/pushsync/pusher.go similarity index 53% rename from storage/pushsync/pusher.go rename to pushsync/pusher.go index 13a4c8e919..860bc61d14 100644 --- a/storage/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -18,7 +18,7 @@ package pushsync import ( "context" - "fmt" + "encoding/hex" "time" "github.com/ethereum/go-ethereum/metrics" @@ -43,43 +43,41 @@ type DB interface { // Pusher takes care of the push syncing type Pusher struct { - nnf func(storage.Address) bool // determines if self address is closer to a chunk - store DB // localstore DB - tags *chunk.Tags // tags to update counts - quit chan struct{} // channel to signal quitting on all loops - pushed map[string]*pushedItem // cache of items push-synced - receipts chan *receiptMsg // channel to receive receipts - ps PubSub // PubSub interface to send chunks and receive receipts + store DB // localstore DB + tags *chunk.Tags // tags to update counts + quit chan struct{} // channel to signal quitting on all loops + pushed map[string]*pushedItem // cache of items push-synced + receipts chan []byte // channel to receive receipts + ps PubSub // PubSub interface to send chunks and receive receipts } var ( - retryInterval = 30 * time.Second // seconds to wait before retry sync + retryInterval = 100 * time.Millisecond // seconds to wait before retry sync ) // pushedItem captures the info needed for the pusher about a chunk during the // push-sync--receipt roundtrip type pushedItem struct { - tag *chunk.Tag // tag for the chunk - sentAt time.Time // most recently sent at time - synced bool // set when chunk got synced - - // roundtrip span - sp opentracing.Span + tag *chunk.Tag // tag for the chunk + shortcut bool // if the chunk receipt was sent by self + firstSentAt time.Time // first sent at time + lastSentAt time.Time // most recently sent at time + synced bool // set when chunk got synced + span opentracing.Span // roundtrip span } // NewPusher contructs a Pusher and starts up the push sync protocol // takes // - a DB interface to subscribe to push sync index to allow iterating over recently stored chunks // - a pubsub interface to send chunks and receive statements of custody -// - tags that hold the several tag -func NewPusher(store DB, ps PubSub, tags *chunk.Tags, nnf func(storage.Address) bool) *Pusher { +// - tags that hold the tags +func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { p := &Pusher{ - nnf: nnf, store: store, tags: tags, quit: make(chan struct{}), pushed: make(map[string]*pushedItem), - receipts: make(chan *receiptMsg), + receipts: make(chan []byte), ps: ps, } go p.sync() @@ -100,11 +98,11 @@ func (p *Pusher) Close() { // a file or collection func (p *Pusher) sync() { var chunks <-chan chunk.Chunk - var cancel, stop func() - var ctx context.Context - var synced []storage.Address + var unsubscribe func() + var syncedAddrs []storage.Address + var syncedItems []*pushedItem - // timer + // timer, initially set to 0 to fall through select case on timer.C for initialisation timer := time.NewTimer(0) defer timer.Stop() @@ -116,34 +114,57 @@ func (p *Pusher) sync() { chunksInBatch := -1 var batchStartTime time.Time + ctx := context.Background() + + var average uint64 = 1000 + var measurements uint64 for { select { // retry interval timer triggers starting from new case <-timer.C: + // initially timer is set to go off as well as every time we hit the end of push index + // so no wait for retryInterval needed to set items synced metrics.GetOrRegisterCounter("pusher.subscribe-push", nil).Inc(1) - // TODO: implement some smart retry strategy relying on sent/synced ratio change // if subscribe was running, stop it - if stop != nil { - stop() + if unsubscribe != nil { + unsubscribe() + } + + log.Debug("set chunk status to synced, insert to db GC index") + syncedTags := make(map[uint32]int) + // set chunk status to synced, insert to db GC index + if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { + log.Error("error setting chunks to synced", "err", err) + continue + } + for i, item := range syncedItems { + // increment synced count for the tag if exists + tag := item.tag + if tag != nil { + syncedTags[tag.Uid] = syncedTags[tag.Uid] + 1 + item.span.Finish() + } + delete(p.pushed, syncedAddrs[i].Hex()) } - for _, addr := range synced { - // set chunk status to synced, insert to db GC index - if err := p.store.Set(context.Background(), chunk.ModeSetSync, addr); err != nil { - log.Warn("error setting chunk to synced", "addr", addr, "err", err) - continue + // iterate over tags in this batch + for uid, n := range syncedTags { + tag, _ := p.tags.Get(uid) + tag.IncN(chunk.StateSynced, n) + if tag.Done(chunk.StateSynced) { + log.Info("closing root span for tag", "taguid", tag.Uid, "tagname", tag.Name) + tag.FinishRootSpan() } - delete(p.pushed, addr.Hex()) } // reset synced list - synced = nil + syncedAddrs = nil + syncedItems = nil // we don't want to record the first iteration if chunksInBatch != -1 { // this measurement is not a timer, but we want a histogram, so it fits the data structure metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.hist", nil).Update(time.Duration(chunksInBatch)) - metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.time", nil).UpdateSince(batchStartTime) metrics.GetOrRegisterCounter("pusher.subscribe-push.chunks-in-batch", nil).Inc(int64(chunksInBatch)) } @@ -151,84 +172,74 @@ func (p *Pusher) sync() { batchStartTime = time.Now() // and start iterating on Push index from the beginning - ctx, cancel = context.WithCancel(context.Background()) - chunks, stop = p.store.SubscribePush(ctx) + chunks, unsubscribe = p.store.SubscribePush(ctx) // reset timer to go off after retryInterval timer.Reset(retryInterval) // handle incoming chunks case ch, more := <-chunks: - func() { - chunksInBatch++ - // if no more, set to nil and wait for timer - if !more { - chunks = nil - return - } + // if no more, set to nil, reset timer to 0 to finalise batch immediately + if !more { + chunks = nil + timer.Reset(0) + break + } - metrics.GetOrRegisterCounter("pusher.send-chunk", nil).Inc(1) - // if no need to sync this chunk then continue - if !p.needToSync(ch) { - return - } + chunksInBatch++ + metrics.GetOrRegisterCounter("pusher.send-chunk", nil).Inc(1) + // if no need to sync this chunk then continue + if !p.needToSync(ch) { + break + } - metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) - // send the chunk and ignore the error - go func(ch chunk.Chunk) { - if err := p.sendChunkMsg(ch); err != nil { - log.Error("error sending chunk", "addr", ch.Address(), "err", err) - } - }(ch) - }() + metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) + // send the chunk and ignore the error + // go func(ch chunk.Chunk) { + if err := p.sendChunkMsg(ch); err != nil { + log.Error("error sending chunk", "addr", ch.Address().Hex(), "err", err) + } // handle incoming receipts - case rec := <-p.receipts: - addr := chunk.Address(rec.Addr) - origin := rec.Origin - func() { - metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) - log.Debug("synced", "addr", addr) - // ignore if already received receipt - item, found := p.pushed[addr.Hex()] - if !found { - metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) - log.Debug("not wanted or already got... ignore", "addr", addr) - return - } - if item.synced { - metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) - log.Debug("just synced... ignore", "addr", addr) - return - } - - timediff := time.Since(item.sentAt) - log.Debug("time to sync", "dur", timediff) - - metrics.GetOrRegisterResettingTimer("pusher.chunk.roundtrip", nil).Update(timediff) - - metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) - // collect synced addresses - synced = append(synced, addr) - // set synced flag - item.synced = true - // increment synced count for the tag if exists - if item.tag != nil { - item.tag.Inc(chunk.StateSynced) - - item.sp.LogFields(olog.String("ro", fmt.Sprintf("%x", origin))) - item.sp.Finish() + case addr := <-p.receipts: + hexaddr := hex.EncodeToString(addr) + log.Debug("synced", "addr", hexaddr) + metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) + // ignore if already received receipt + item, found := p.pushed[hexaddr] + if !found { + metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) + log.Debug("not wanted or already got... ignore", "addr", hexaddr) + break + } + if item.synced { + metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) + log.Debug("just synced... ignore", "addr", hexaddr) + break + } - if item.tag.DoneSyncing() { - log.Info("closing root span for tag", "taguid", item.tag.Uid, "tagname", item.tag.Name) - item.tag.FinishRootSpan() - } + totalDuration := time.Since(item.firstSentAt) + if !item.shortcut { + roundtripDuration := time.Since(item.lastSentAt) + measurement := uint64(roundtripDuration) / 1000 + if 2*measurement < 3*average { + average = (measurements*average + measurement) / (measurements + 1) + measurements++ + retryInterval = time.Duration(average*2) * time.Millisecond + log.Debug("time to sync", "addr", hexaddr, "total duration", totalDuration, "roundtrip duration", roundtripDuration, "n", measurements, "average", average, "retry", retryInterval) } - }() + } + metrics.GetOrRegisterResettingTimer("pusher.chunk.roundtrip", nil).Update(totalDuration) + metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) + // collect synced addresses and corresponding items to do subsequent batch operations + syncedAddrs = append(syncedAddrs, addr) + syncedItems = append(syncedItems, item) + // set synced flag + item.synced = true case <-p.quit: - // if there was a subscription, cancel it - if cancel != nil { - cancel() + // if subscribe was running, stop it + if unsubscribe != nil { + unsubscribe() } return } @@ -244,20 +255,14 @@ func (p *Pusher) handleReceiptMsg(msg []byte) error { return err } log.Debug("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) - p.pushReceipt(receipt.Addr, receipt.Origin) + p.pushReceipt(receipt.Addr) return nil } // pushReceipt just inserts the address into the channel -// it is also called by the push sync Storer if the originator and storer identical -func (p *Pusher) pushReceipt(addr []byte, origin []byte) { - r := &receiptMsg{ - addr, - origin, - []byte{}, - } +func (p *Pusher) pushReceipt(addr []byte) { select { - case p.receipts <- r: + case p.receipts <- addr: case <-p.quit: } } @@ -287,7 +292,9 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { // needToSync checks if a chunk needs to be push-synced: // * if not sent yet OR -// * if sent but more then retryInterval ago, so need resend +// * if sent but more than retryInterval ago, so need resend OR +// * if self is closest node to chunk TODO: and not light node +// in this case send receipt to self to trigger synced state on chunk func (p *Pusher) needToSync(ch chunk.Chunk) bool { item, found := p.pushed[ch.Address().Hex()] // has been pushed already @@ -296,72 +303,41 @@ func (p *Pusher) needToSync(ch chunk.Chunk) bool { if item.synced { return false } - // too early to retry - if item.sentAt.Add(retryInterval).After(time.Now()) { - return false - } + item.lastSentAt = time.Now() // first time encountered } else { addr := ch.Address() - + hexaddr := addr.Hex() // remember item tag, _ := p.tags.Get(ch.TagID()) + now := time.Now() item = &pushedItem{ - tag: tag, + tag: tag, + firstSentAt: now, + lastSentAt: now, } - // should i sync?? - if !p.nnf(addr) { - // no => - - // mark as synced - // set chunk status to synced, insert to db GC index - if err := p.store.Set(context.Background(), chunk.ModeSetSync, addr); err != nil { - log.Warn("error setting chunk to synced", "addr", addr, "err", err) - } - - // set synced flag - item.synced = true - // increment synced count for the tag if exists - if item.tag != nil { - item.tag.Inc(chunk.StateSynced) - - // opentracing for self chunks that don't need syncing? - _, osp := spancontext.StartSpan( - tag.Tctx, - "chunk.mine") - osp.LogFields(olog.String("ref", ch.Address().String())) - osp.SetTag("addr", ch.Address().String()) - osp.Finish() - - if item.tag.DoneSyncing() { - log.Info("closing root span for tag", "taguid", item.tag.Uid, "tagname", item.tag.Name) - item.tag.FinishRootSpan() - } - } - - return false - } - // i should sync - // increment SENT count on tag if it exists if tag != nil { tag.Inc(chunk.StateSent) - // opentracing for chunk roundtrip - _, osp := spancontext.StartSpan( - tag.Tctx, - "chunk.sent") - osp.LogFields(olog.String("ref", ch.Address().String())) - osp.SetTag("addr", ch.Address().String()) + _, span := spancontext.StartSpan(tag.Context(), "chunk.sent") + span.LogFields(olog.String("ref", hexaddr)) + span.SetTag("addr", hexaddr) - item.sp = osp + item.span = span } // remember the item - p.pushed[ch.Address().Hex()] = item + p.pushed[hexaddr] = item + if p.ps.IsClosestTo(addr) { + log.Debug("self is closest to ref: push receipt locally", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) + item.shortcut = true + go p.pushReceipt(addr) + return false + } + log.Debug("self is not the closest to ref: send chunk to neighbourhood", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) } - item.sentAt = time.Now() return true } diff --git a/storage/pushsync/pusher_test.go b/pushsync/pusher_test.go similarity index 63% rename from storage/pushsync/pusher_test.go rename to pushsync/pusher_test.go index 7bd7db169e..30a30c018b 100644 --- a/storage/pushsync/pusher_test.go +++ b/pushsync/pusher_test.go @@ -23,7 +23,6 @@ import ( "fmt" "math/rand" "sync" - "sync/atomic" "testing" "time" @@ -32,13 +31,12 @@ import ( "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" - "github.com/ethersphere/swarm/network" "github.com/ethersphere/swarm/storage" colorable "github.com/mattn/go-colorable" ) var ( - loglevel = flag.Int("loglevel", 3, "verbosity of logs") + loglevel = flag.Int("loglevel", 0, "verbosity of logs") ) func init() { @@ -47,18 +45,34 @@ func init() { log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*loglevel), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) } +type testPubSub struct { + *loopBack + isClosestTo func([]byte) bool +} + +var testBaseAddr = make([]byte, 32) + +// BaseAddr needed to implement PubSub interface +// in the testPubSub, this address has no relevant and is given only for logging +func (tps *testPubSub) BaseAddr() []byte { + return testBaseAddr +} + +// IsClosestTo needed to implement PubSub interface +func (tps *testPubSub) IsClosestTo(addr []byte) bool { + return tps.isClosestTo(addr) +} + // loopback implements PubSub as a central subscription engine, // ie a msg sent is received by all handlers registered for the topic type loopBack struct { async bool - addr []byte handlers map[string][]func(msg []byte, p *p2p.Peer) error } func newLoopBack(async bool) *loopBack { return &loopBack{ async: async, - addr: make([]byte, 32), handlers: make(map[string][]func(msg []byte, p *p2p.Peer) error), } } @@ -73,7 +87,12 @@ func (lb *loopBack) Register(topic string, _ bool, handler func(msg []byte, p *p // that topic func (lb *loopBack) Send(to []byte, topic string, msg []byte) error { if lb.async { - go lb.send(to, topic, msg) + go func() { + if !delayResponse() { + return + } + lb.send(to, topic, msg) + }() return nil } return lb.send(to, topic, msg) @@ -82,18 +101,15 @@ func (lb *loopBack) Send(to []byte, topic string, msg []byte) error { func (lb *loopBack) send(to []byte, topic string, msg []byte) error { p := p2p.NewPeer(enode.ID{}, "", nil) for _, handler := range lb.handlers[topic] { + log.Debug("handling message", "topic", topic, "to", hex.EncodeToString(to)) if err := handler(msg, p); err != nil { + log.Warn("error handling message", "topic", topic, "to", hex.EncodeToString(to)) return err } } return nil } -// BaseAddr needed to implement PubSub interface -func (lb *loopBack) BaseAddr() []byte { - return lb.addr -} - // testPushSyncIndex mocks localstore and provides subscription and setting synced status // it implements the DB interface type testPushSyncIndex struct { @@ -120,9 +136,9 @@ func newTestPushSyncIndex(chunkCnt int, tagIDs []uint32, tags *chunk.Tags, sent // we keep track of an index so that each call to SubscribePush knows where to start // generating the new fake hashes // Before the new fake hashes it iterates over hashes not synced yet -func (t *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chunk, func()) { +func (tp *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chunk, func()) { chunks := make(chan storage.Chunk) - tagCnt := len(t.tagIDs) + tagCnt := len(tp.tagIDs) quit := make(chan struct{}) stop := func() { close(quit) } go func() { @@ -132,14 +148,17 @@ func (t *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chunk // generate fake hashes that encode the chunk order addr := make([]byte, 32) binary.BigEndian.PutUint64(addr, uint64(i)) + tagID := tp.tagIDs[i%tagCnt] // remember when the chunk was put // if sent again, dont modify the time - t.sent.Store(i, time.Now()) - // increment stored count on tag - tagID := t.tagIDs[i%tagCnt] - if tag, _ := t.tags.Get(tagID); tag != nil { - tag.Inc(chunk.StateStored) + _, loaded := tp.sent.LoadOrStore(i, time.Now()) + if !loaded { + // increment stored count on tag + if tag, _ := tp.tags.Get(tagID); tag != nil { + tag.Inc(chunk.StateStored) + } } + tp.sent.Store(i, time.Now()) select { // chunks have no data and belong to tag i%tagCount case chunks <- storage.NewChunk(addr, nil).WithTagID(tagID): @@ -149,27 +168,26 @@ func (t *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chunk } } // push the chunks already pushed but not yet synced - t.sent.Range(func(k, _ interface{}) bool { - log.Debug("resending", "cur", k) + tp.sent.Range(func(k, _ interface{}) bool { + log.Debug("resending", "idx", k) return feed(k.(int)) }) // generate the new chunks from t.i - for t.i < t.total && feed(t.i) { - t.i++ + for tp.i < tp.total && feed(tp.i) { + tp.i++ } - - log.Debug("sent all chunks", "total", t.total) + log.Debug("sent chunks", "sent", tp.i, "total", tp.total) close(chunks) }() return chunks, stop } -func (t *testPushSyncIndex) Set(ctx context.Context, _ chunk.ModeSet, addrs ...storage.Address) error { +func (tp *testPushSyncIndex) Set(ctx context.Context, _ chunk.ModeSet, addrs ...storage.Address) error { for _, addr := range addrs { - cur := int(binary.BigEndian.Uint64(addr[:8])) - t.sent.Delete(cur) - t.synced <- cur - log.Debug("set chunk synced", "cur", cur, "addr", addr) + idx := int(binary.BigEndian.Uint64(addr[:8])) + tp.sent.Delete(idx) + tp.synced <- idx + log.Debug("set chunk synced", "idx", idx, "addr", addr) } return nil } @@ -193,18 +211,15 @@ func delayResponse() bool { // after a random delay // The test checks: // - if sync function is called on chunks in order of insertion (FIFO) -// - repeated sending is attempted only if retryInterval time passed // - already synced chunks are not resynced // - if no more data inserted, the db is emptied shortly func TestPusher(t *testing.T) { - timeout := 10 * time.Second - chunkCnt := 200 + chunkCnt := 1024 tagCnt := 4 errc := make(chan error) sent := &sync.Map{} - sendTimes := make(map[int]time.Time) synced := make(map[int]int) quit := make(chan struct{}) defer close(quit) @@ -216,7 +231,7 @@ func TestPusher(t *testing.T) { } } - ps := newLoopBack(false) + lb := newLoopBack(false) max := 0 // the highest index sent so far respond := func(msg []byte, _ *p2p.Peer) error { @@ -226,29 +241,11 @@ func TestPusher(t *testing.T) { return nil } // check outgoing chunk messages - cur := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) - if cur > max { - errf("incorrect order of chunks from db chunk #%d before #%d", cur, max) - return nil - } - v, found := sent.Load(cur) - previouslySentAt, repeated := sendTimes[cur] - if !found { - if !repeated { - errf("chunk #%d not sent but received", cur) - } + idx := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) + if idx > max { + errf("incorrect order of chunks from db chunk #%d before #%d", idx, max) return nil } - sentAt := v.(time.Time) - if repeated { - // expect at least retryInterval since previous push - if expectedAt := previouslySentAt.Add(retryInterval); expectedAt.After(sentAt) { - errf("resync chunk #%d too early. previously sent at %v, next at %v < expected at %v", cur, previouslySentAt, sentAt, expectedAt) - return nil - } - } - // remember the latest time sent - sendTimes[cur] = sentAt max++ // respond ~ mock storer protocol go func() { @@ -257,14 +254,14 @@ func TestPusher(t *testing.T) { if err != nil { errf("error encoding receipt message: %v", err) } - log.Debug("chunk sent", "addr", hex.EncodeToString(receipt.Addr)) + log.Debug("chunk sent", "idx", idx) // random delay to allow retries if !delayResponse() { - log.Debug("chunk/receipt lost", "addr", hex.EncodeToString(receipt.Addr)) + log.Debug("chunk/receipt lost", "idx", idx) return } - log.Debug("store chunk, send receipt", "addr", hex.EncodeToString(receipt.Addr)) - err = ps.Send(chmsg.Origin, pssReceiptTopic, rmsg) + log.Debug("store chunk, send receipt", "idx", idx) + err = lb.Send(chmsg.Origin, pssReceiptTopic, rmsg) if err != nil { errf("error sending receipt message: %v", err) } @@ -272,13 +269,12 @@ func TestPusher(t *testing.T) { return nil } // register the respond function - ps.Register(pssChunkTopic, false, respond) + lb.Register(pssChunkTopic, false, respond) tags, tagIDs := setupTags(chunkCnt, tagCnt) // construct the mock push sync index iterator tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) // start push syncing in a go routine - kad := network.NewKademlia(nil, network.NewKadParams()) - p := NewPusher(tp, ps, tags, kad) + p := NewPusher(tp, &testPubSub{lb, func([]byte) bool { return false }}, tags) defer p.Close() // collect synced chunks until all chunks synced // wait on errc for errors on any thread @@ -286,7 +282,6 @@ func TestPusher(t *testing.T) { for { select { case i := <-tp.synced: - sent.Delete(i) n := synced[i] synced[i] = n + 1 if len(synced) == chunkCnt { @@ -327,95 +322,32 @@ func checkTags(t *testing.T, expTotal int, tagIDs []uint32, tags *chunk.Tags) { for _, tagID := range tagIDs { tag, err := tags.Get(tagID) if err != nil { - t.Fatalf("expected no error getting tag '%v', got %v", tagID, err) + t.Fatalf("expected no error getting tag %v, got %v", tagID, err) + } + // the tag is adjusted after the store.Set calls show + err = tag.WaitTillDone(context.Background(), chunk.StateSynced) + if err != nil { + t.Fatalf("error waiting for syncing on tag %v: %v", tagID, err) } n, total, err := tag.Status(chunk.StateSent) if err != nil { - t.Fatalf("getting status for tag '%v', expected no error, got %v", tagID, err) + t.Fatalf("getting status for tag %v, expected no error, got %v", tagID, err) } if int(n) != expTotal { - t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + t.Fatalf("expected Sent count on tag %v to be %v, got %v", tagID, expTotal, n) } if int(total) != expTotal { - t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + t.Fatalf("expected Sent total count on tag %v to be %v, got %v", tagID, expTotal, n) } n, total, err = tag.Status(chunk.StateSynced) if err != nil { - t.Fatalf("getting status for tag '%v', expected no error, got %v", tagID, err) + t.Fatalf("getting status for tag %v, expected no error, got %v\n%v", tagID, err, tag) } if int(n) != expTotal { - t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) + t.Fatalf("expected Synced count on tag %v to be %v, got %v\n%v", tagID, expTotal, n, tag) } if int(total) != expTotal { - t.Fatalf("expected Sent count on tag '%v' to be %v, got %v", tagID, expTotal, n) - } - } -} - -type testStore struct { - store *sync.Map -} - -func (t *testStore) Put(_ context.Context, _ chunk.ModePut, ch chunk.Chunk) (bool, error) { - cur := binary.BigEndian.Uint64(ch.Address()[:8]) - var storedCnt uint32 = 1 - v, loaded := t.store.LoadOrStore(cur, &storedCnt) - if loaded { - atomic.AddUint32(v.(*uint32), 1) - } - return false, nil -} - -// TestPushSyncAndStoreWithLoopbackPubSub tests the push sync protocol -// push syncer node communicate with storers via mock PubSub -func TestPushSyncAndStoreWithLoopbackPubSub(t *testing.T) { - timeout := 10 * time.Second - chunkCnt := 2000 - tagCnt := 4 - storerCnt := 3 - sent := &sync.Map{} - store := &sync.Map{} - // mock pubsub messenger - ps := newLoopBack(true) - - tags, tagIDs := setupTags(chunkCnt, tagCnt) - // construct the mock push sync index iterator - tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) - // neighbourhood function mocked - nnf := func(storage.Address) bool { return true } - // start push syncing in a go routine - p := NewPusher(tp, ps, tags, nnf) - defer p.Close() - - // set up a number of storers - storers := make([]*Storer, storerCnt) - for i := 0; i < storerCnt; i++ { - storers[i] = NewStorer(&testStore{store}, ps, nnf, p.pushReceipt) - } - - synced := 0 - for { - select { - case i := <-tp.synced: - synced++ - sent.Delete(i) - if synced == chunkCnt { - expTotal := chunkCnt / tagCnt - checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) - for i := uint64(0); i < uint64(chunkCnt); i++ { - v, ok := store.Load(i) - if !ok { - t.Fatalf("chunk %v not stored", i) - } - if cnt := *(v.(*uint32)); cnt != uint32(storerCnt) { - t.Fatalf("chunk %v expected to be saved %v times, got %v", i, storerCnt, cnt) - } - } - return - } - case <-time.After(timeout): - t.Fatalf("timeout waiting for all chunks to be synced") + t.Fatalf("expected Synced total count on tag %v to be %v, got %v", tagID, expTotal, n) } } - } diff --git a/storage/pushsync/pushsync_simulation_test.go b/pushsync/simulation_test.go similarity index 75% rename from storage/pushsync/pushsync_simulation_test.go rename to pushsync/simulation_test.go index 70271724d7..a4e98254b8 100644 --- a/storage/pushsync/pushsync_simulation_test.go +++ b/pushsync/simulation_test.go @@ -18,6 +18,8 @@ package pushsync import ( "context" + "encoding/hex" + "flag" "fmt" "io/ioutil" "math/rand" @@ -47,45 +49,56 @@ var ( bucketKeyNetStore = simulation.BucketKey("netstore") ) +var ( + nodeCntFlag = flag.Int("nodes", 16, "number of nodes in simulation") + chunkCntFlag = flag.Int("chunks", 16, "number of chunks per upload in simulation") + testCasesFlag = flag.Int("cases", 16, "number of concurrent upload-download cases to test in simulation") +) + // test syncer using pss // the test // * creates a simulation with connectivity loaded from a snapshot -// * for each trial, two nodes are chosen randomly, an uploader and a downloader +// * for each test case, two nodes are chosen randomly, an uploader and a downloader // * uploader uploads a number of chunks // * wait until the uploaded chunks are synced // * downloader downloads the chunk -// Trials are run concurrently +// Testcasrs are run concurrently func TestPushSyncSimulation(t *testing.T) { - nodeCnt := 16 - chunkCnt := 500 - testcases := 10 - err := testSyncerWithPubSub(t, nodeCnt, chunkCnt, testcases, newServiceFunc) + nodeCnt := *nodeCntFlag + chunkCnt := *chunkCntFlag + testcases := *testCasesFlag + + err := testSyncerWithPubSub(nodeCnt, chunkCnt, testcases, newServiceFunc) if err != nil { t.Fatal(err) } } -func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, testcases int, sf simulation.ServiceFunc) error { - t.Helper() +func testSyncerWithPubSub(nodeCnt, chunkCnt, testcases int, sf simulation.ServiceFunc) error { sim := simulation.NewInProc(map[string]simulation.ServiceFunc{ - "streamer": sf, + "pushsync": sf, }) defer sim.Close() ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) defer cancel() - err := sim.UploadSnapshot(ctx, fmt.Sprintf("../../network/stream/testing/snapshot_%d.json", nodeCnt)) + err := sim.UploadSnapshot(ctx, fmt.Sprintf("../network/stream/testing/snapshot_%d.json", nodeCnt)) if err != nil { - t.Fatal(err) + return err } - log.Info("Snapshot loaded") - time.Sleep(2 * time.Second) + log.Debug("Snapshot loaded") result := sim.Run(ctx, func(ctx context.Context, sim *simulation.Simulation) error { - time.Sleep(2 * time.Second) errc := make(chan error) - for i := 0; i < testcases; i++ { - go uploadAndDownload(ctx, sim, errc, nodeCnt, chunkCnt, i) + for j := 0; j < testcases; j++ { + j := j + go func() { + err := uploadAndDownload(ctx, sim, nodeCnt, chunkCnt, j) + select { + case errc <- err: + case <-ctx.Done(): + } + }() } i := 0 for err := range errc { @@ -94,14 +107,14 @@ func testSyncerWithPubSub(t *testing.T, nodeCnt, chunkCnt, testcases int, sf sim } i++ if i >= testcases { - break + return nil } } return nil }) if result.Error != nil { - t.Fatalf("simulation error: %v", result.Error) + return fmt.Errorf("simulation error: %v", result.Error) } return nil } @@ -116,13 +129,12 @@ func pickNodes(n int) (i, j int) { return } -func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, errc chan error, nodeCnt, chunkCnt, i int) { +func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, nodeCnt, chunkCnt, i int) error { // chose 2 random nodes as uploader and downloader u, d := pickNodes(nodeCnt) // setup uploader node uid := sim.UpNodeIDs()[u] - val, _ := sim.NodeItem(uid, bucketKeyPushSyncer) - p := val.(*Pusher) + p := sim.MustNodeItem(uid, bucketKeyPushSyncer).(*Pusher) // setup downloader node did := sim.UpNodeIDs()[d] // the created tag indicates the uploader and downloader nodes @@ -130,28 +142,26 @@ func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, errc cha log.Debug("uploading", "peer", uid, "chunks", chunkCnt, "tagname", tagname) tag, what, err := upload(ctx, p.store.(*localstore.DB), p.tags, tagname, chunkCnt) if err != nil { - select { - case errc <- err: - case <-ctx.Done(): - return - } - return + return err } + log.Debug("uploaded", "peer", uid, "chunks", chunkCnt, "tagname", tagname) - // wait till synced - for !tag.DoneSyncing() { - time.Sleep(100 * time.Millisecond) + // wait till pushsync is done + syncTimeout := 30 * time.Second + sctx, cancel := context.WithTimeout(ctx, syncTimeout) + err = tag.WaitTillDone(sctx, chunk.StateSynced) + if err != nil { + log.Debug("tag", "tag", tag) + cancel() + return fmt.Errorf("error waiting syncing: %v", err) } + cancel() - log.Debug("synced", "peer", uid, "chunks", chunkCnt, "tagname", tagname) log.Debug("downloading", "peer", did, "chunks", chunkCnt, "tagname", tagname) - val, _ = sim.NodeItem(did, bucketKeyNetStore) - netstore := val.(*storage.NetStore) - select { - case errc <- download(ctx, netstore, what): - case <-ctx.Done(): - } - log.Debug("downloaded", "peer", did, "chunks", chunkCnt, "tagname", tagname) + netstore := sim.MustNodeItem(did, bucketKeyNetStore).(*storage.NetStore) + err = download(ctx, netstore, what) + log.Debug("downloaded", "peer", did, "chunks", chunkCnt, "tagname", tagname, "err", err) + return err } // newServiceFunc constructs a minimal service needed for a simulation test for Push Sync, namely: @@ -184,29 +194,29 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } - // streamer + // // streamer for retrieval delivery := stream.NewDelivery(kad, netStore) netStore.RemoteGet = delivery.RequestFromPeers bucket.Store(bucketKeyNetStore, netStore) + // set up syncer noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled, SyncUpdateDelay: 50 * time.Millisecond} r := stream.NewRegistry(addr.ID(), delivery, netStore, state.NewInmemoryStore(), noSyncing, nil) pubSub := pss.NewPubSub(ps) - - // set up syncer - p := NewPusher(lstore, pubSub, chunk.NewTags(), kad) + // setup pusher + p := NewPusher(lstore, pubSub, chunk.NewTags()) bucket.Store(bucketKeyPushSyncer, p) // setup storer - s := NewStorer(netStore, pubSub, kad, p.pushReceipt) + s := NewStorer(netStore, pubSub) cleanup := func() { + r.Close() p.Close() s.Close() netStore.Close() - r.Close() os.RemoveAll(dir) } @@ -247,7 +257,10 @@ func upload(ctx context.Context, store Store, tags *chunk.Tags, tagname string, for i := 0; i < n; i++ { ch := storage.GenerateRandomChunk(int64(chunk.DefaultSize)) addrs = append(addrs, ch.Address()) - store.Put(ctx, chunk.ModePutUpload, ch.WithTagID(tag.Uid)) + _, err := store.Put(ctx, chunk.ModePutUpload, ch.WithTagID(tag.Uid)) + if err != nil { + return nil, nil, err + } tag.Inc(chunk.StateStored) } return tag, addrs, nil @@ -258,6 +271,7 @@ func download(ctx context.Context, store *storage.NetStore, addrs []storage.Addr for _, addr := range addrs { go func(addr storage.Address) { _, err := store.Get(ctx, chunk.ModeGetRequest, storage.NewRequest(addr)) + log.Debug("Get", "addr", hex.EncodeToString(addr[:]), "err", err) select { case errc <- err: case <-ctx.Done(): diff --git a/storage/pushsync/storer.go b/pushsync/storer.go similarity index 66% rename from storage/pushsync/storer.go rename to pushsync/storer.go index be2159bded..c288c0f651 100644 --- a/storage/pushsync/storer.go +++ b/pushsync/storer.go @@ -17,16 +17,13 @@ package pushsync import ( - "bytes" "context" "encoding/hex" - "fmt" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" - "github.com/ethersphere/swarm/network" "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" olog "github.com/opentracing/opentracing-go/log" @@ -35,16 +32,14 @@ import ( // Store is the storage interface to save chunks // NetStore implements this interface type Store interface { - Put(context.Context, chunk.ModePut, chunk.Chunk) (bool, error) + Put(context.Context, chunk.ModePut, ...chunk.Chunk) ([]bool, error) } // Storer is the object used by the push-sync server side protocol type Storer struct { - kad *network.Kademlia - store Store // store to put chunks in, and retrieve them - ps PubSub // pubsub interface to receive chunks and send receipts - deregister func() // deregister the registered handler when Storer is closed - pushReceipt func(addr []byte, origin []byte) // to be called... + store Store // store to put chunks in, and retrieve them from + ps PubSub // pubsub interface to receive chunks and send receipts + deregister func() // deregister the registered handler when Storer is closed } // NewStorer constructs a Storer @@ -54,12 +49,10 @@ type Storer struct { // - the chunks are stored and synced to their nearest neighbours and // - a statement of custody receipt is sent as a response to the originator // it sets a cancel function that deregisters the handler -func NewStorer(store Store, ps PubSub, kad *network.Kademlia, pushReceipt func(addr []byte, origin []byte)) *Storer { +func NewStorer(store Store, ps PubSub) *Storer { s := &Storer{ - kad: kad, - store: store, - ps: ps, - pushReceipt: pushReceipt, + store: store, + ps: ps, } s.deregister = ps.Register(pssChunkTopic, true, func(msg []byte, _ *p2p.Peer) error { return s.handleChunkMsg(msg) @@ -85,9 +78,9 @@ func (s *Storer) handleChunkMsg(msg []byte) error { context.TODO(), "handle.chunk.msg") defer osp.Finish() - osp.LogFields(olog.String("ref", fmt.Sprintf("%x", chmsg.Addr))) - osp.SetTag("addr", fmt.Sprintf("%x", chmsg.Addr)) - log.Debug("Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin), "self", fmt.Sprintf("%x", s.ps.BaseAddr())) + osp.LogFields(olog.String("ref", hex.EncodeToString(chmsg.Addr))) + osp.SetTag("addr", hex.EncodeToString(chmsg.Addr)) + log.Debug("Storer Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin), "self", hex.EncodeToString(s.ps.BaseAddr())) return s.processChunkMsg(chmsg) } @@ -104,17 +97,12 @@ func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { return err } - closerPeer := s.kad.CloserPeerThanMeXOR(chmsg.Addr) - - log.Trace("closer than me", "ref", fmt.Sprintf("%x", chmsg.Addr), "res", closerPeer) - // if there is closer peer, do not send back a receipt - if closerPeer { - return nil + // if self is closest peer then send back a receipt + if s.ps.IsClosestTo(chmsg.Addr) { + log.Debug("self is closest to ref", "ref", hex.EncodeToString(chmsg.Addr), "self", hex.EncodeToString(s.ps.BaseAddr())) + return s.sendReceiptMsg(chmsg) } - - // TODO: check if originator or relayer is a nearest neighbour then return - // otherwise send back receipt - return s.sendReceiptMsg(chmsg) + return nil } // sendReceiptMsg sends a statement of custody receipt message @@ -125,22 +113,13 @@ func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { context.TODO(), "send.receipt") defer osp.Finish() - osp.LogFields(olog.String("ref", fmt.Sprintf("%x", chmsg.Addr))) - osp.SetTag("addr", fmt.Sprintf("%x", chmsg.Addr)) - - // if origin is self, use direct channel, no pubsub send needed - if bytes.Equal(chmsg.Origin, s.ps.BaseAddr()) { - osp.LogFields(olog.String("origin", "self")) - - go s.pushReceipt(chmsg.Addr, chmsg.Origin) - return nil - } - osp.LogFields(olog.String("origin", fmt.Sprintf("%x", chmsg.Origin))) + osp.LogFields(olog.String("ref", hex.EncodeToString(chmsg.Addr))) + osp.SetTag("addr", hex.EncodeToString(chmsg.Addr)) + osp.LogFields(olog.String("origin", hex.EncodeToString(chmsg.Origin))) rmsg := &receiptMsg{ - Addr: chmsg.Addr, - Origin: s.ps.BaseAddr(), // receipt origin is who is sending back the receipt - Nonce: newNonce(), + Addr: chmsg.Addr, + Nonce: newNonce(), } msg, err := rlp.EncodeToBytes(rmsg) if err != nil { diff --git a/swarm.go b/swarm.go index 323d71c1c8..96717501c0 100644 --- a/swarm.go +++ b/swarm.go @@ -52,13 +52,13 @@ import ( "github.com/ethersphere/swarm/network/stream/v2" "github.com/ethersphere/swarm/p2p/protocols" "github.com/ethersphere/swarm/pss" + "github.com/ethersphere/swarm/pushsync" "github.com/ethersphere/swarm/state" "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/storage/feed" "github.com/ethersphere/swarm/storage/localstore" "github.com/ethersphere/swarm/storage/mock" "github.com/ethersphere/swarm/storage/pin" - "github.com/ethersphere/swarm/storage/pushsync" "github.com/ethersphere/swarm/swap" "github.com/ethersphere/swarm/tracing" ) @@ -245,10 +245,10 @@ func NewSwarm(config *api.Config, mockStore *mock.NodeStore) (self *Swarm, err e } pubsub := pss.NewPubSub(self.ps) - self.pushSync = pushsync.NewPusher(localStore, pubsub, tags) + self.pushSync = pushsync.NewPusher(localStore, pubsub, self.tags) self.storer = pushsync.NewStorer(self.netStore, pubsub) - self.api = api.NewAPI(self.fileStore, self.dns, feedsHandler, self.privateKey, tags) + self.api = api.NewAPI(self.fileStore, self.dns, feedsHandler, self.privateKey, self.tags) // Instantiate the pinAPI object with the already opened localstore self.pinAPI = pin.NewAPI(localStore, self.stateStore, self.config.FileStoreParams, self.tags, self.api) From 9e6ec3c984bbd699ee9255c589dfb548dc1723c7 Mon Sep 17 00:00:00 2001 From: zelig Date: Mon, 2 Sep 2019 14:22:39 +0200 Subject: [PATCH 13/22] api, chunk, network, pss, pushsync: act on review comments - introduce custom logger on pusher/storer - dynamic setting of retryinterval extracted - timeout changed back - fix and use testutil.checkTags - use tag context - tags.Create and NewTag has context argument - fix pusher.Close before localstore --- api/api_test.go | 18 +++--- api/client/client_test.go | 8 +-- api/http/middleware.go | 3 +- api/http/server.go | 15 ++--- api/http/server_test.go | 4 +- api/inspector.go | 5 +- api/pullsync/client.go | 14 +++++ api/pullsync/server.go | 9 +++ chunk/chunk.go | 16 ----- chunk/tag.go | 4 +- chunk/tag_test.go | 8 ++- chunk/tags.go | 4 +- chunk/tags_test.go | 13 ++-- chunk/testing/tag.go | 3 +- network/timeouts/timeouts.go | 2 +- network_test.go | 13 ++-- pss/pss.go | 6 +- pushsync/protocol.go | 17 +++-- pushsync/protocol_test.go | 25 ++++++-- pushsync/pusher.go | 116 +++++++++++++++++++---------------- pushsync/pusher_test.go | 49 +++++---------- pushsync/simulation_test.go | 39 ++++++------ pushsync/storer.go | 48 +++++++-------- storage/chunker_test.go | 4 +- storage/filestore.go | 6 +- storage/hasherstore_test.go | 2 +- storage/netstore.go | 6 +- storage/pin/pin.go | 4 +- swarm.go | 3 - swarm_test.go | 10 +-- 30 files changed, 239 insertions(+), 235 deletions(-) create mode 100644 api/pullsync/client.go create mode 100644 api/pullsync/server.go diff --git a/api/api_test.go b/api/api_test.go index b2dbebf8a6..d29b3af9ff 100644 --- a/api/api_test.go +++ b/api/api_test.go @@ -141,7 +141,7 @@ func TestApiPut(t *testing.T) { resp := testGet(t, api, addr.Hex(), "") checkResponse(t, resp, exp) tag := tags.All()[0] - chunktesting.CheckTag(t, tag, 2, 2, 0, 2) //1 chunk data, 1 chunk manifest + chunktesting.CheckTag(t, tag, 2, 2, 0, 0, 0, 2) //1 chunk data, 1 chunk manifest }) } @@ -150,7 +150,7 @@ func TestApiTagLarge(t *testing.T) { const contentLength = 4096 * 4095 testAPI(t, func(api *API, tags *chunk.Tags, toEncrypt bool) { randomContentReader := io.LimitReader(crand.Reader, int64(contentLength)) - tag, err := api.Tags.Create("unnamed-tag", 0) + tag, err := api.Tags.Create(context.Background(), "unnamed-tag", 0) if err != nil { t.Fatal(err) } @@ -168,11 +168,11 @@ func TestApiTagLarge(t *testing.T) { if toEncrypt { tag := tags.All()[0] expect := int64(4095 + 64 + 1) - chunktesting.CheckTag(t, tag, expect, expect, 0, expect) + chunktesting.CheckTag(t, tag, expect, expect, 0, 0, 0, expect) } else { tag := tags.All()[0] expect := int64(4095 + 32 + 1) - chunktesting.CheckTag(t, tag, expect, expect, 0, expect) + chunktesting.CheckTag(t, tag, expect, expect, 0, 0, 0, expect) } }) } @@ -549,18 +549,18 @@ func TestDetectContentType(t *testing.T) { // putString provides singleton manifest creation on top of api.API func putString(ctx context.Context, a *API, content string, contentType string, toEncrypt bool) (k storage.Address, wait func(context.Context) error, err error) { r := strings.NewReader(content) - tag, err := a.Tags.Create("unnamed-tag", 0) + tag, err := a.Tags.Create(ctx, "unnamed-tag", 0) - log.Trace("created new tag", "uid", tag.Uid) + log.Trace("created new tag", "id", tag.Uid) - cCtx := sctx.SetTag(ctx, tag.Uid) - key, waitContent, err := a.Store(cCtx, r, int64(len(content)), toEncrypt) + ctx = sctx.SetTag(ctx, tag.Uid) + key, waitContent, err := a.Store(ctx, r, int64(len(content)), toEncrypt) if err != nil { return nil, nil, err } manifest := fmt.Sprintf(`{"entries":[{"hash":"%v","contentType":"%s"}]}`, key, contentType) r = strings.NewReader(manifest) - key, waitManifest, err := a.Store(cCtx, r, int64(len(manifest)), toEncrypt) + key, waitManifest, err := a.Store(ctx, r, int64(len(manifest)), toEncrypt) if err != nil { return nil, nil, err } diff --git a/api/client/client_test.go b/api/client/client_test.go index a7e63310a6..a69c4d103d 100644 --- a/api/client/client_test.go +++ b/api/client/client_test.go @@ -51,7 +51,7 @@ func TestClientUploadDownloadRaw(t *testing.T) { // check the tag was created successfully tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 1, 1, 0, 1) + chunktesting.CheckTag(t, tag, 1, 1, 0, 0, 0, 1) } func TestClientUploadDownloadRawEncrypted(t *testing.T) { @@ -69,7 +69,7 @@ func TestClientUploadDownloadRawEncrypted(t *testing.T) { // check the tag was created successfully tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 1, 1, 0, 1) + chunktesting.CheckTag(t, tag, 1, 1, 0, 0, 0, 1) } func testClientUploadDownloadRaw(srv *swarmhttp.TestSwarmServer, toEncrypt bool, t *testing.T, data []byte, toPin bool) string { @@ -228,7 +228,7 @@ func TestClientUploadDownloadDirectory(t *testing.T) { // check the tag was created successfully tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 9, 9, 0, 9) + chunktesting.CheckTag(t, tag, 8, 8, 0, 0, 0, 8) // check we can download the individual files checkDownloadFile := func(path string, expected []byte) { @@ -372,7 +372,7 @@ func TestClientMultipartUpload(t *testing.T) { // check the tag was created successfully tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 9, 9, 0, 9) + chunktesting.CheckTag(t, tag, 8, 8, 0, 0, 0, 8) // check we can download the individual files checkDownloadFile := func(path string) { diff --git a/api/http/middleware.go b/api/http/middleware.go index 9952247983..2cd2c0cbdf 100644 --- a/api/http/middleware.go +++ b/api/http/middleware.go @@ -1,6 +1,7 @@ package http import ( + "context" "fmt" "net/http" "runtime/debug" @@ -123,7 +124,7 @@ func InitUploadTag(h http.Handler, tags *chunk.Tags) http.Handler { log.Trace("creating tag", "tagName", tagName, "estimatedTotal", estimatedTotal) - t, err := tags.Create(tagName, estimatedTotal) + t, err := tags.Create(context.Background(), tagName, estimatedTotal) if err != nil { log.Error("error creating tag", "err", err, "tagName", tagName) } diff --git a/api/http/server.go b/api/http/server.go index 028034ac01..a3e48b2c5d 100644 --- a/api/http/server.go +++ b/api/http/server.go @@ -358,9 +358,7 @@ func (s *Server) HandlePostFiles(w http.ResponseWriter, r *http.Request) { log.Error("handle post raw got an error retrieving tag", "tagUID", tagUID, "err", err) } - ctx := r.Context() - - _, sp := spancontext.StartSpan(tag.Context(), "http.post") + ctx, sp := spancontext.StartSpan(tag.Context(), "http.post") defer sp.Finish() contentType, params, err := mime.ParseMediaType(r.Header.Get("Content-Type")) @@ -1151,7 +1149,7 @@ func isDecryptError(err error) bool { // periodicTagTrace queries the tag every 2 seconds and logs its state to the span func periodicTagTrace(tags *chunk.Tags, tagUID uint32, q chan struct{}, sp opentracing.Span) { - f := func() { + report := func() { tag, err := tags.Get(tagUID) if err != nil { log.Error("error while getting tag", "tagUID", tagUID, "err", err) @@ -1163,13 +1161,10 @@ func periodicTagTrace(tags *chunk.Tags, tagUID uint32, q chan struct{}, sp opent for { select { case <-q: - f() - + report() return - default: - f() - - time.Sleep(2 * time.Second) + case <-time.After(2 * time.Second): + report() } } } diff --git a/api/http/server_test.go b/api/http/server_test.go index d9a94b3f0f..1e5d810ce9 100644 --- a/api/http/server_test.go +++ b/api/http/server_test.go @@ -945,7 +945,7 @@ func testBzzTar(encrypted bool, t *testing.T) { // check that the tag was written correctly tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 4, 4, 0, 4) + chunktesting.CheckTag(t, tag, 3, 3, 0, 0, 0, 3) swarmHash, err := ioutil.ReadAll(resp2.Body) resp2.Body.Close() @@ -1081,7 +1081,7 @@ func TestBzzCorrectTagEstimate(t *testing.T) { <-time.After(10 * time.Millisecond) case 1: tag := srv.Tags.All()[0] - chunktesting.CheckTag(t, tag, 0, 0, 0, v.expChunks) + chunktesting.CheckTag(t, tag, 0, 0, 0, 0, 0, v.expChunks) srv.Tags.Delete(tag.Uid) done = true } diff --git a/api/inspector.go b/api/inspector.go index 1bdd912706..e48ed6d6c0 100644 --- a/api/inspector.go +++ b/api/inspector.go @@ -55,15 +55,12 @@ func (i *Inspector) KademliaInfo() network.KademliaInfo { } func (i *Inspector) IsPushSynced(tagname string) bool { - log.Info("is push synced", "tagname", tagname) tags := i.api.Tags.All() for _, t := range tags { if t.Name == tagname { ds := t.Done(chunk.StateSynced) - - log.Debug("found tag", "tagname", tagname, "done-syncing", ds) - + log.Trace("found tag", "tagname", tagname, "done-syncing", ds) return ds } } diff --git a/api/pullsync/client.go b/api/pullsync/client.go new file mode 100644 index 0000000000..922f1d98ae --- /dev/null +++ b/api/pullsync/client.go @@ -0,0 +1,14 @@ +package pullsync + +import stream "github.com/ethersphere/swarm/network/stream/v2" + + + +// the node-wide pullsync.Client +type Client struct { + stream.Syncer // embed stream.Syncer + // when pullsync + // here you simply put the update sync logic listening to kademlia depth changes + // and call `Request` + // remember the request, when no longer relevant just call request.Cancel() +} diff --git a/api/pullsync/server.go b/api/pullsync/server.go new file mode 100644 index 0000000000..17fe44e169 --- /dev/null +++ b/api/pullsync/server.go @@ -0,0 +1,9 @@ +package pullsync + +// pullSync.Server implements stream.Provider +// uses localstore SubscribePull for the bins +// server is node-wide +type Server struct { + // ... + *stream.LocalProvider +} diff --git a/chunk/chunk.go b/chunk/chunk.go index 765ede4be4..50de9c1c56 100644 --- a/chunk/chunk.go +++ b/chunk/chunk.go @@ -119,22 +119,6 @@ func (a *Address) UnmarshalJSON(value []byte) error { return nil } -// XOR stores (a xor b) in dst, stopping when the end of any slice is -// reached. It returns the number of bytes xor'd. -func XOR(dst, a, b []byte) int { - n := len(a) - if len(b) < n { - n = len(b) - } - if len(dst) < n { - n = len(dst) - } - for i := 0; i < n; i++ { - dst[i] = a[i] ^ b[i] - } - return n -} - // Proximity returns the proximity order of the MSB distance between x and y // // The distance metric MSB(x, y) of two equal length byte sequences x an y is the diff --git a/chunk/tag.go b/chunk/tag.go index 507e05118a..c1a96eeb3e 100644 --- a/chunk/tag.go +++ b/chunk/tag.go @@ -65,7 +65,7 @@ type Tag struct { // New creates a new tag, stores it by the name and returns it // it returns an error if the tag with this name already exists -func NewTag(uid uint32, s string, total int64) *Tag { +func NewTag(ctx context.Context, uid uint32, s string, total int64) *Tag { t := &Tag{ Uid: uid, Name: s, @@ -73,7 +73,7 @@ func NewTag(uid uint32, s string, total int64) *Tag { Total: total, } - t.ctx, t.span = spancontext.StartSpan(context.Background(), "new.upload.tag") + t.ctx, t.span = spancontext.StartSpan(ctx, "new.upload.tag") return t } diff --git a/chunk/tag_test.go b/chunk/tag_test.go index c57094a6b7..3e71bf3bba 100644 --- a/chunk/tag_test.go +++ b/chunk/tag_test.go @@ -18,6 +18,7 @@ package chunk import ( "bytes" + "context" "sync" "testing" "time" @@ -137,12 +138,13 @@ func TestTagConcurrentIncrements(t *testing.T) { // TestTagsMultipleConcurrentIncrements tests Inc calls concurrently func TestTagsMultipleConcurrentIncrementsSyncMap(t *testing.T) { ts := NewTags() + ctx := context.Background() n := 100 wg := sync.WaitGroup{} wg.Add(10 * 5 * n) for i := 0; i < 10; i++ { s := string([]byte{uint8(i)}) - tag, err := ts.Create(s, int64(n)) + tag, err := ts.Create(ctx, s, int64(n)) if err != nil { t.Fatal(err) } @@ -183,7 +185,7 @@ func TestTagsMultipleConcurrentIncrementsSyncMap(t *testing.T) { // TestMarshallingWithAddr tests that marshalling and unmarshalling is done correctly when the // tag Address (byte slice) contains some arbitrary value func TestMarshallingWithAddr(t *testing.T) { - tg := NewTag(111, "test/tag", 10) + tg := NewTag(context.Background(), 111, "test/tag", 10) tg.Address = []byte{0, 1, 2, 3, 4, 5, 6} for _, f := range allStates { @@ -231,7 +233,7 @@ func TestMarshallingWithAddr(t *testing.T) { // TestMarshallingNoAddress tests that marshalling and unmarshalling is done correctly func TestMarshallingNoAddr(t *testing.T) { - tg := NewTag(111, "test/tag", 10) + tg := NewTag(context.Background(), 111, "test/tag", 10) for _, f := range allStates { tg.Inc(f) } diff --git a/chunk/tags.go b/chunk/tags.go index c3ca4ab939..2697e3f0cf 100644 --- a/chunk/tags.go +++ b/chunk/tags.go @@ -42,7 +42,7 @@ func NewTags() *Tags { // Create creates a new tag, stores it by the name and returns it // it returns an error if the tag with this name already exists -func (ts *Tags) Create(s string, total int64) (*Tag, error) { +func (ts *Tags) Create(ctx context.Context, s string, total int64) (*Tag, error) { t := &Tag{ Uid: uint32(rand.Int31()), Name: s, @@ -53,7 +53,7 @@ func (ts *Tags) Create(s string, total int64) (*Tag, error) { return nil, errExists } - t.ctx, t.span = spancontext.StartSpan(context.Background(), "new.upload.tag") + t.ctx, t.span = spancontext.StartSpan(ctx, "new.upload.tag") return t, nil } diff --git a/chunk/tags_test.go b/chunk/tags_test.go index db9c16b85b..cd82787d74 100644 --- a/chunk/tags_test.go +++ b/chunk/tags_test.go @@ -16,13 +16,16 @@ package chunk -import "testing" +import ( + "context" + "testing" +) func TestAll(t *testing.T) { ts := NewTags() - - ts.Create("1", 1) - ts.Create("2", 1) + ctx := context.Background() + ts.Create(ctx, "1", 1) + ts.Create(ctx, "2", 1) all := ts.All() @@ -38,7 +41,7 @@ func TestAll(t *testing.T) { t.Fatalf("expected tag 1 Total to be 1 got %d", n) } - ts.Create("3", 1) + ts.Create(ctx, "3", 1) all = ts.All() if len(all) != 3 { diff --git a/chunk/testing/tag.go b/chunk/testing/tag.go index f785c51227..d4f34c07f7 100644 --- a/chunk/testing/tag.go +++ b/chunk/testing/tag.go @@ -23,12 +23,11 @@ import ( ) // CheckTag checks the first tag in the api struct to be in a certain state -func CheckTag(t *testing.T, tag *chunk.Tag, split, stored, seen, total int64) { +func CheckTag(t *testing.T, tag *chunk.Tag, split, stored, seen, sent, synced, total int64) { t.Helper() if tag == nil { t.Fatal("no tag found") } - tSplit := tag.Get(chunk.StateSplit) if tSplit != split { t.Fatalf("should have had split chunks, got %d want %d", tSplit, split) diff --git a/network/timeouts/timeouts.go b/network/timeouts/timeouts.go index ca71d79584..b92af3b47b 100644 --- a/network/timeouts/timeouts.go +++ b/network/timeouts/timeouts.go @@ -11,7 +11,7 @@ var FailedPeerSkipDelay = 20 * time.Second var FetcherGlobalTimeout = 10 * time.Second // SearchTimeout is the max time requests wait for a peer to deliver a chunk, after which another peer is tried -var SearchTimeout = 2000 * time.Millisecond +var SearchTimeout = 500 * time.Millisecond // SyncerClientWaitTimeout is the max time a syncer client waits for a chunk to be delivered during syncing var SyncerClientWaitTimeout = 20 * time.Second diff --git a/network_test.go b/network_test.go index 4001eb274f..91fbcb452f 100644 --- a/network_test.go +++ b/network_test.go @@ -29,9 +29,6 @@ import ( "testing" "time" - "github.com/ethersphere/swarm/sctx" - "github.com/ethersphere/swarm/testutil" - "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/node" @@ -39,7 +36,9 @@ import ( "github.com/ethereum/go-ethereum/p2p/simulations/adapters" "github.com/ethersphere/swarm/api" "github.com/ethersphere/swarm/network/simulation" + "github.com/ethersphere/swarm/sctx" "github.com/ethersphere/swarm/storage" + "github.com/ethersphere/swarm/testutil" ) var ( @@ -483,18 +482,18 @@ func retrieveF( // putString provides singleton manifest creation on top of api.API func putString(ctx context.Context, a *api.API, content string, contentType string, toEncrypt bool) (k storage.Address, wait func(context.Context) error, err error) { r := strings.NewReader(content) - tag, err := a.Tags.Create("unnamed-tag", 0) + tag, err := a.Tags.Create(ctx, "unnamed-tag", 0) log.Trace("created new tag", "uid", tag.Uid) - cCtx := sctx.SetTag(ctx, tag.Uid) - key, waitContent, err := a.Store(cCtx, r, int64(len(content)), toEncrypt) + ctx = sctx.SetTag(ctx, tag.Uid) + key, waitContent, err := a.Store(ctx, r, int64(len(content)), toEncrypt) if err != nil { return nil, nil, err } manifest := fmt.Sprintf(`{"entries":[{"hash":"%v","contentType":"%s"}]}`, key, contentType) r = strings.NewReader(manifest) - key, waitManifest, err := a.Store(cCtx, r, int64(len(manifest)), toEncrypt) + key, waitManifest, err := a.Store(ctx, r, int64(len(manifest)), toEncrypt) if err != nil { return nil, nil, err } diff --git a/pss/pss.go b/pss/pss.go index 2c6df9e838..98f13a6608 100644 --- a/pss/pss.go +++ b/pss/pss.go @@ -483,9 +483,9 @@ func (p *Pss) handle(ctx context.Context, msg interface{}) error { // raw is simplest handler contingency to check, so check that first var isRaw bool if pssmsg.isRaw() { - if capabilities, ok := p.getTopicHandlerCaps(Topic(psstopic)); ok { + if capabilities, ok := p.getTopicHandlerCaps(psstopic); ok { if !capabilities.raw { - log.Debug("No handler for raw message", "topic", label(psstopic[:])) + log.Warn("No handler for raw message", "topic", label(psstopic[:])) return nil } } @@ -497,7 +497,7 @@ func (p *Pss) handle(ctx context.Context, msg interface{}) error { // - prox handler on message and we are in prox regardless of partial address match // store this result so we don't calculate again on every handler var isProx bool - if capabilities, ok := p.getTopicHandlerCaps(Topic(psstopic)); ok { + if capabilities, ok := p.getTopicHandlerCaps(psstopic); ok { isProx = capabilities.prox } isRecipient := p.isSelfPossibleRecipient(pssmsg, isProx) diff --git a/pushsync/protocol.go b/pushsync/protocol.go index 093e5d36ac..41b00e99a4 100644 --- a/pushsync/protocol.go +++ b/pushsync/protocol.go @@ -1,23 +1,24 @@ -// Copyright 2019 The go-ethereum Authors -// This file is part of the go-ethereum library. +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. // -// The go-ethereum library is free software: you can redistribute it and/or modify +// The Swarm library is free software: you can redistribute it and/or modify // it under the terms of the GNU Lesser General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. // -// The go-ethereum library is distributed in the hope that it will be useful, +// The Swarm library is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU Lesser General Public License for more details. // // You should have received a copy of the GNU Lesser General Public License -// along with the go-ethereum library. If not, see . +// along with the Swarm library. If not, see . package pushsync import ( "crypto/rand" + "io" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/p2p" @@ -75,11 +76,7 @@ func decodeReceiptMsg(msg []byte) (*receiptMsg, error) { // even without POC it is important otherwise resending a chunk is deduplicated by pss func newNonce() []byte { buf := make([]byte, 32) - t := 0 - for t < len(buf) { - n, _ := rand.Read(buf[t:]) - t += n - } + io.ReadFull(rand.Reader, buf) return buf } diff --git a/pushsync/protocol_test.go b/pushsync/protocol_test.go index 82746b085d..e00db4bc62 100644 --- a/pushsync/protocol_test.go +++ b/pushsync/protocol_test.go @@ -1,3 +1,19 @@ +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. +// +// The Swarm library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The Swarm library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the Swarm library. If not, see . + package pushsync import ( @@ -72,7 +88,7 @@ func TestProtocol(t *testing.T) { n := synced[idx] synced[idx] = n + 1 if len(synced) == chunkCnt { - expTotal := chunkCnt / tagCnt + expTotal := int64(chunkCnt / tagCnt) checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) for i := uint64(0); i < uint64(chunkCnt); i++ { if n := synced[int(i)]; n != 1 { @@ -82,10 +98,9 @@ func TestProtocol(t *testing.T) { if !ok { t.Fatalf("chunk %v not stored", i) } - _ = v - // if cnt := *(v.(*uint32)); cnt < uint32(storerCnt) { - // t.Fatalf("chunk %v expected to be saved at least %v times, got %v", i, storerCnt, cnt) - // } + if cnt := *(v.(*uint32)); cnt < uint32(storerCnt) { + t.Fatalf("chunk %v expected to be saved at least %v times, got %v", i, storerCnt, cnt) + } } return } diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 860bc61d14..0442fd3fa3 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -1,31 +1,32 @@ -// Copyright 2019 The go-ethereum Authors -// This file is part of the go-ethereum library. +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. // -// The go-ethereum library is free software: you can redistribute it and/or modify +// The Swarm library is free software: you can redistribute it and/or modify // it under the terms of the GNU Lesser General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. // -// The go-ethereum library is distributed in the hope that it will be useful, +// The Swarm library is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU Lesser General Public License for more details. // // You should have received a copy of the GNU Lesser General Public License -// along with the go-ethereum library. If not, see . +// along with the Swarm library. If not, see . package pushsync import ( "context" "encoding/hex" + "fmt" "time" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" - "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" "github.com/opentracing/opentracing-go" @@ -43,17 +44,18 @@ type DB interface { // Pusher takes care of the push syncing type Pusher struct { - store DB // localstore DB - tags *chunk.Tags // tags to update counts - quit chan struct{} // channel to signal quitting on all loops - pushed map[string]*pushedItem // cache of items push-synced - receipts chan []byte // channel to receive receipts - ps PubSub // PubSub interface to send chunks and receive receipts + store DB // localstore DB + tags *chunk.Tags // tags to update counts + quit chan struct{} // channel to signal quitting on all loops + closed chan struct{} // channel to signal sync loop terminated + pushed map[string]*pushedItem // cache of items push-synced + receipts chan []byte // channel to receive receipts + ps PubSub // PubSub interface to send chunks and receive receipts + logger log.Logger // custom logger + retryInterval time.Duration // dynamically adjusted time interval between retriess } -var ( - retryInterval = 100 * time.Millisecond // seconds to wait before retry sync -) +const maxMeasurements = 20000 // pushedItem captures the info needed for the pusher about a chunk during the // push-sync--receipt roundtrip @@ -73,12 +75,15 @@ type pushedItem struct { // - tags that hold the tags func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { p := &Pusher{ - store: store, - tags: tags, - quit: make(chan struct{}), - pushed: make(map[string]*pushedItem), - receipts: make(chan []byte), - ps: ps, + store: store, + tags: tags, + quit: make(chan struct{}), + closed: make(chan struct{}), + pushed: make(map[string]*pushedItem), + receipts: make(chan []byte), + ps: ps, + logger: log.New("self", hex.EncodeToString(ps.BaseAddr())), + retryInterval: 100 * time.Millisecond, } go p.sync() return p @@ -87,6 +92,7 @@ func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { // Close closes the pusher func (p *Pusher) Close() { close(p.quit) + <-p.closed } // sync starts a forever loop that pushes chunks to their neighbourhood @@ -101,7 +107,7 @@ func (p *Pusher) sync() { var unsubscribe func() var syncedAddrs []storage.Address var syncedItems []*pushedItem - + defer close(p.closed) // timer, initially set to 0 to fall through select case on timer.C for initialisation timer := time.NewTimer(0) defer timer.Stop() @@ -116,7 +122,7 @@ func (p *Pusher) sync() { var batchStartTime time.Time ctx := context.Background() - var average uint64 = 1000 + var average uint64 = 100000 // microseconds var measurements uint64 for { @@ -132,12 +138,10 @@ func (p *Pusher) sync() { unsubscribe() } - log.Debug("set chunk status to synced, insert to db GC index") syncedTags := make(map[uint32]int) // set chunk status to synced, insert to db GC index if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { - log.Error("error setting chunks to synced", "err", err) - continue + panic(fmt.Sprintf("pushsync: error setting chunks to synced: %v", err)) } for i, item := range syncedItems { // increment synced count for the tag if exists @@ -153,7 +157,7 @@ func (p *Pusher) sync() { tag, _ := p.tags.Get(uid) tag.IncN(chunk.StateSynced, n) if tag.Done(chunk.StateSynced) { - log.Info("closing root span for tag", "taguid", tag.Uid, "tagname", tag.Name) + p.logger.Debug("closing root span for tag", "taguid", tag.Uid, "tagname", tag.Name) tag.FinishRootSpan() } } @@ -174,7 +178,7 @@ func (p *Pusher) sync() { // and start iterating on Push index from the beginning chunks, unsubscribe = p.store.SubscribePush(ctx) // reset timer to go off after retryInterval - timer.Reset(retryInterval) + timer.Reset(p.retryInterval) // handle incoming chunks case ch, more := <-chunks: @@ -196,48 +200,40 @@ func (p *Pusher) sync() { // send the chunk and ignore the error // go func(ch chunk.Chunk) { if err := p.sendChunkMsg(ch); err != nil { - log.Error("error sending chunk", "addr", ch.Address().Hex(), "err", err) + p.logger.Error("error sending chunk", "addr", ch.Address().Hex(), "err", err) } // handle incoming receipts case addr := <-p.receipts: hexaddr := hex.EncodeToString(addr) - log.Debug("synced", "addr", hexaddr) + p.logger.Trace("got receipt", "addr", hexaddr) metrics.GetOrRegisterCounter("pusher.receipts.all", nil).Inc(1) // ignore if already received receipt item, found := p.pushed[hexaddr] if !found { metrics.GetOrRegisterCounter("pusher.receipts.not-found", nil).Inc(1) - log.Debug("not wanted or already got... ignore", "addr", hexaddr) + p.logger.Trace("not wanted or already got... ignore", "addr", hexaddr) break } - if item.synced { + if item.synced { // already got receipt in this same batch metrics.GetOrRegisterCounter("pusher.receipts.already-synced", nil).Inc(1) - log.Debug("just synced... ignore", "addr", hexaddr) + p.logger.Trace("just synced... ignore", "addr", hexaddr) break } + // calibrate retryInterval based on roundtrip times totalDuration := time.Since(item.firstSentAt) - if !item.shortcut { - roundtripDuration := time.Since(item.lastSentAt) - measurement := uint64(roundtripDuration) / 1000 - if 2*measurement < 3*average { - average = (measurements*average + measurement) / (measurements + 1) - measurements++ - retryInterval = time.Duration(average*2) * time.Millisecond - log.Debug("time to sync", "addr", hexaddr, "total duration", totalDuration, "roundtrip duration", roundtripDuration, "n", measurements, "average", average, "retry", retryInterval) - } - } metrics.GetOrRegisterResettingTimer("pusher.chunk.roundtrip", nil).Update(totalDuration) metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) + + measurements, average = p.updateRetryInterval(item, measurements, average) + // collect synced addresses and corresponding items to do subsequent batch operations syncedAddrs = append(syncedAddrs, addr) syncedItems = append(syncedItems, item) - // set synced flag item.synced = true case <-p.quit: - // if subscribe was running, stop it if unsubscribe != nil { unsubscribe() } @@ -254,7 +250,7 @@ func (p *Pusher) handleReceiptMsg(msg []byte) error { if err != nil { return err } - log.Debug("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) + p.logger.Trace("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) p.pushReceipt(receipt.Addr) return nil } @@ -282,7 +278,7 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { if err != nil { return err } - log.Debug("send chunk", "addr", label(ch.Address()), "self", label(p.ps.BaseAddr())) + p.logger.Trace("send chunk", "addr", label(ch.Address()), "self", label(p.ps.BaseAddr())) metrics.GetOrRegisterResettingTimer("pusher.send.chunk.rlp", nil).UpdateSince(rlpTimer) @@ -297,21 +293,20 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { // in this case send receipt to self to trigger synced state on chunk func (p *Pusher) needToSync(ch chunk.Chunk) bool { item, found := p.pushed[ch.Address().Hex()] + now := time.Now() // has been pushed already if found { // has synced already since subscribe called if item.synced { return false } - item.lastSentAt = time.Now() - // first time encountered + item.lastSentAt = now } else { - + // first time encountered addr := ch.Address() hexaddr := addr.Hex() // remember item tag, _ := p.tags.Get(ch.TagID()) - now := time.Now() item = &pushedItem{ tag: tag, firstSentAt: now, @@ -332,12 +327,27 @@ func (p *Pusher) needToSync(ch chunk.Chunk) bool { // remember the item p.pushed[hexaddr] = item if p.ps.IsClosestTo(addr) { - log.Debug("self is closest to ref: push receipt locally", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) + p.logger.Trace("self is closest to ref: push receipt locally", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) item.shortcut = true go p.pushReceipt(addr) return false } - log.Debug("self is not the closest to ref: send chunk to neighbourhood", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) + p.logger.Trace("self is not the closest to ref: send chunk to neighbourhood", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) } return true } + +// updateRetryInterval calibrates the period after which push index iterator restart from the beginning +func (p *Pusher) updateRetryInterval(item *pushedItem, measurements uint64, average uint64) (uint64, uint64) { + if !item.shortcut { // only real network roundtrips counted, no shortcuts + roundtripDuration := time.Since(item.lastSentAt) + measurement := uint64(roundtripDuration) / 1000 // in microseconds + // recalculate average + average = (measurements*average + measurement) / (measurements + 1) + if measurement < maxMeasurements { + measurements++ + } + p.retryInterval = time.Duration(average*2) * time.Microsecond + } + return measurements, average +} diff --git a/pushsync/pusher_test.go b/pushsync/pusher_test.go index 30a30c018b..1c0d8852b7 100644 --- a/pushsync/pusher_test.go +++ b/pushsync/pusher_test.go @@ -1,18 +1,19 @@ -// Copyright 2019 The go-ethereum Authors -// This file is part of the go-ethereum library. +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. // -// The go-ethereum library is free software: you can redistribute it and/or modify +// The Swarm library is free software: you can redistribute it and/or modify // it under the terms of the GNU Lesser General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. // -// The go-ethereum library is distributed in the hope that it will be useful, +// The Swarm library is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU Lesser General Public License for more details. // // You should have received a copy of the GNU Lesser General Public License -// along with the go-ethereum library. If not, see . +// along with the Swarm library. If not, see . + package pushsync import ( @@ -32,6 +33,7 @@ import ( "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/storage" + "github.com/ethersphere/swarm/testutil" colorable "github.com/mattn/go-colorable" ) @@ -103,7 +105,7 @@ func (lb *loopBack) send(to []byte, topic string, msg []byte) error { for _, handler := range lb.handlers[topic] { log.Debug("handling message", "topic", topic, "to", hex.EncodeToString(to)) if err := handler(msg, p); err != nil { - log.Warn("error handling message", "topic", topic, "to", hex.EncodeToString(to)) + log.Error("error handling message", "topic", topic, "to", hex.EncodeToString(to)) return err } } @@ -172,7 +174,7 @@ func (tp *testPushSyncIndex) SubscribePush(context.Context) (<-chan storage.Chun log.Debug("resending", "idx", k) return feed(k.(int)) }) - // generate the new chunks from t.i + // generate the new chunks from tp.i for tp.i < tp.total && feed(tp.i) { tp.i++ } @@ -285,7 +287,7 @@ func TestPusher(t *testing.T) { n := synced[i] synced[i] = n + 1 if len(synced) == chunkCnt { - expTotal := chunkCnt / tagCnt + expTotal := int64(chunkCnt / tagCnt) checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) return } @@ -307,7 +309,7 @@ func setupTags(chunkCnt, tagCnt int) (tags *chunk.Tags, tagIDs []uint32) { tags = chunk.NewTags() // all but one tag is created for i := 0; i < tagCnt-1; i++ { - tags.Create("", int64(chunkCnt/tagCnt)) + tags.Create(context.Background(), "", int64(chunkCnt/tagCnt)) } // extract tag ids tags.Range(func(k, _ interface{}) bool { @@ -318,36 +320,19 @@ func setupTags(chunkCnt, tagCnt int) (tags *chunk.Tags, tagIDs []uint32) { return tags, append(tagIDs, 0) } -func checkTags(t *testing.T, expTotal int, tagIDs []uint32, tags *chunk.Tags) { +func checkTags(t *testing.T, expTotal int64, tagIDs []uint32, tags *chunk.Tags) { + t.Helper() for _, tagID := range tagIDs { tag, err := tags.Get(tagID) if err != nil { - t.Fatalf("expected no error getting tag %v, got %v", tagID, err) + t.Fatal(err) } // the tag is adjusted after the store.Set calls show err = tag.WaitTillDone(context.Background(), chunk.StateSynced) if err != nil { - t.Fatalf("error waiting for syncing on tag %v: %v", tagID, err) - } - n, total, err := tag.Status(chunk.StateSent) - if err != nil { - t.Fatalf("getting status for tag %v, expected no error, got %v", tagID, err) - } - if int(n) != expTotal { - t.Fatalf("expected Sent count on tag %v to be %v, got %v", tagID, expTotal, n) - } - if int(total) != expTotal { - t.Fatalf("expected Sent total count on tag %v to be %v, got %v", tagID, expTotal, n) - } - n, total, err = tag.Status(chunk.StateSynced) - if err != nil { - t.Fatalf("getting status for tag %v, expected no error, got %v\n%v", tagID, err, tag) - } - if int(n) != expTotal { - t.Fatalf("expected Synced count on tag %v to be %v, got %v\n%v", tagID, expTotal, n, tag) - } - if int(total) != expTotal { - t.Fatalf("expected Synced total count on tag %v to be %v, got %v", tagID, expTotal, n) + t.Fatalf("error waiting for syncing on tag %v: %v", tag.Uid, err) } + + testutil.CheckTag(t, tag, 0, expTotal, 0, expTotal, expTotal, expTotal) } } diff --git a/pushsync/simulation_test.go b/pushsync/simulation_test.go index a4e98254b8..0b4ddbac41 100644 --- a/pushsync/simulation_test.go +++ b/pushsync/simulation_test.go @@ -1,18 +1,18 @@ -// Copyright 2019 The go-ethereum Authors -// This file is part of the go-ethereum library. +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. // -// The go-ethereum library is free software: you can redistribute it and/or modify +// The Swarm library is free software: you can redistribute it and/or modify // it under the terms of the GNU Lesser General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. // -// The go-ethereum library is distributed in the hope that it will be useful, +// The Swarm library is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU Lesser General Public License for more details. // // You should have received a copy of the GNU Lesser General Public License -// along with the go-ethereum library. If not, see . +// along with the Swarm library. If not, see . package pushsync @@ -24,6 +24,7 @@ import ( "io/ioutil" "math/rand" "os" + "path/filepath" "sync" "testing" "time" @@ -31,7 +32,6 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/node" "github.com/ethereum/go-ethereum/p2p" - "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/p2p/simulations/adapters" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" @@ -62,8 +62,8 @@ var ( // * uploader uploads a number of chunks // * wait until the uploaded chunks are synced // * downloader downloads the chunk -// Testcasrs are run concurrently -func TestPushSyncSimulation(t *testing.T) { +// Testcases are run concurrently +func TestPushsyncSimulation(t *testing.T) { nodeCnt := *nodeCntFlag chunkCnt := *chunkCntFlag testcases := *testCasesFlag @@ -80,14 +80,16 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, testcases int, sf simulation.Servic }) defer sim.Close() - ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second) + ctx := context.Background() + snapCtx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() - err := sim.UploadSnapshot(ctx, fmt.Sprintf("../network/stream/testing/snapshot_%d.json", nodeCnt)) + err := sim.UploadSnapshot(snapCtx, filepath.Join("../network/stream/testing", fmt.Sprintf("snapshot_%d.json", nodeCnt))) if err != nil { - return err + return fmt.Errorf("error while loading snapshot: %v", err) } - log.Debug("Snapshot loaded") + start := time.Now() + log.Info("Snapshot loaded. Simulation starting", "at", start) result := sim.Run(ctx, func(ctx context.Context, sim *simulation.Simulation) error { errc := make(chan error) for j := 0; j < testcases; j++ { @@ -116,6 +118,7 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, testcases int, sf simulation.Servic if result.Error != nil { return fmt.Errorf("simulation error: %v", result.Error) } + log.Error("simulation", "duration", time.Since(start)) return nil } @@ -140,7 +143,7 @@ func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, nodeCnt, // the created tag indicates the uploader and downloader nodes tagname := fmt.Sprintf("tag-%v-%v-%d", label(uid[:]), label(did[:]), i) log.Debug("uploading", "peer", uid, "chunks", chunkCnt, "tagname", tagname) - tag, what, err := upload(ctx, p.store.(*localstore.DB), p.tags, tagname, chunkCnt) + tag, ref, err := upload(ctx, p.store.(*localstore.DB), p.tags, tagname, chunkCnt) if err != nil { return err } @@ -159,7 +162,7 @@ func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, nodeCnt, log.Debug("downloading", "peer", did, "chunks", chunkCnt, "tagname", tagname) netstore := sim.MustNodeItem(did, bucketKeyNetStore).(*storage.NetStore) - err = download(ctx, netstore, what) + err = download(ctx, netstore, ref) log.Debug("downloaded", "peer", did, "chunks", chunkCnt, "tagname", tagname, "err", err) return err } @@ -170,7 +173,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic // setup localstore n := ctx.Config.Node() addr := network.NewAddr(n) - dir, err := ioutil.TempDir("", "localstore-test") + dir, err := ioutil.TempDir("", "pushsync-test") if err != nil { return nil, nil, err } @@ -180,7 +183,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } // setup netstore - netStore := storage.NewNetStore(lstore, enode.ID{}) + netStore := storage.NewNetStore(lstore, n.ID()) // setup pss kadParams := network.NewKadParams() @@ -213,9 +216,9 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic s := NewStorer(netStore, pubSub) cleanup := func() { - r.Close() p.Close() s.Close() + r.Close() netStore.Close() os.RemoveAll(dir) } @@ -250,7 +253,7 @@ func (s *StreamerAndPss) Stop() error { } func upload(ctx context.Context, store Store, tags *chunk.Tags, tagname string, n int) (tag *chunk.Tag, addrs []storage.Address, err error) { - tag, err = tags.Create(tagname, int64(n)) + tag, err = tags.Create(ctx, tagname, int64(n)) if err != nil { return nil, nil, err } diff --git a/pushsync/storer.go b/pushsync/storer.go index c288c0f651..77d14f065f 100644 --- a/pushsync/storer.go +++ b/pushsync/storer.go @@ -1,18 +1,18 @@ -// Copyright 2019 The go-ethereum Authors -// This file is part of the go-ethereum library. +// Copyright 2019 The Swarm Authors +// This file is part of the Swarm library. // -// The go-ethereum library is free software: you can redistribute it and/or modify +// The Swarm library is free software: you can redistribute it and/or modify // it under the terms of the GNU Lesser General Public License as published by // the Free Software Foundation, either version 3 of the License, or // (at your option) any later version. // -// The go-ethereum library is distributed in the hope that it will be useful, +// The Swarm library is distributed in the hope that it will be useful, // but WITHOUT ANY WARRANTY; without even the implied warranty of // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the // GNU Lesser General Public License for more details. // // You should have received a copy of the GNU Lesser General Public License -// along with the go-ethereum library. If not, see . +// along with the Swarm library. If not, see . package pushsync @@ -20,10 +20,10 @@ import ( "context" "encoding/hex" + "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" - "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/spancontext" "github.com/ethersphere/swarm/storage" olog "github.com/opentracing/opentracing-go/log" @@ -37,9 +37,10 @@ type Store interface { // Storer is the object used by the push-sync server side protocol type Storer struct { - store Store // store to put chunks in, and retrieve them from - ps PubSub // pubsub interface to receive chunks and send receipts - deregister func() // deregister the registered handler when Storer is closed + store Store // store to put chunks in, and retrieve them from + ps PubSub // pubsub interface to receive chunks and send receipts + deregister func() // deregister the registered handler when Storer is closed + logger log.Logger // custom logger } // NewStorer constructs a Storer @@ -51,8 +52,9 @@ type Storer struct { // it sets a cancel function that deregisters the handler func NewStorer(store Store, ps PubSub) *Storer { s := &Storer{ - store: store, - ps: ps, + store: store, + ps: ps, + logger: log.New("self", hex.EncodeToString(ps.BaseAddr())), } s.deregister = ps.Register(pssChunkTopic, true, func(msg []byte, _ *p2p.Peer) error { return s.handleChunkMsg(msg) @@ -74,14 +76,12 @@ func (s *Storer) handleChunkMsg(msg []byte) error { return err } - _, osp := spancontext.StartSpan( - context.TODO(), - "handle.chunk.msg") + ctx, osp := spancontext.StartSpan(context.Background(), "handle.chunk.msg") defer osp.Finish() osp.LogFields(olog.String("ref", hex.EncodeToString(chmsg.Addr))) osp.SetTag("addr", hex.EncodeToString(chmsg.Addr)) - log.Debug("Storer Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin), "self", hex.EncodeToString(s.ps.BaseAddr())) - return s.processChunkMsg(chmsg) + s.logger.Trace("Storer Handler", "chunk", label(chmsg.Addr), "origin", label(chmsg.Origin)) + return s.processChunkMsg(ctx, chmsg) } // processChunkMsg processes a chunk received via pss pssChunkTopic @@ -90,17 +90,17 @@ func (s *Storer) handleChunkMsg(msg []byte) error { // chunks that fall within their area of responsibility. // Upon receiving the chunk is saved and a statement of custody // receipt message is sent as a response to the originator. -func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { +func (s *Storer) processChunkMsg(ctx context.Context, chmsg *chunkMsg) error { // TODO: double check if it falls in area of responsibility ch := storage.NewChunk(chmsg.Addr, chmsg.Data) - if _, err := s.store.Put(context.TODO(), chunk.ModePutSync, ch); err != nil { + if _, err := s.store.Put(ctx, chunk.ModePutSync, ch); err != nil { return err } // if self is closest peer then send back a receipt if s.ps.IsClosestTo(chmsg.Addr) { - log.Debug("self is closest to ref", "ref", hex.EncodeToString(chmsg.Addr), "self", hex.EncodeToString(s.ps.BaseAddr())) - return s.sendReceiptMsg(chmsg) + s.logger.Trace("self is closest to ref", "ref", hex.EncodeToString(chmsg.Addr)) + return s.sendReceiptMsg(ctx, chmsg) } return nil } @@ -108,10 +108,8 @@ func (s *Storer) processChunkMsg(chmsg *chunkMsg) error { // sendReceiptMsg sends a statement of custody receipt message // to the originator of a push-synced chunk message. // Including a unique nonce makes the receipt immune to deduplication cache -func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { - _, osp := spancontext.StartSpan( - context.TODO(), - "send.receipt") +func (s *Storer) sendReceiptMsg(ctx context.Context, chmsg *chunkMsg) error { + ctx, osp := spancontext.StartSpan(ctx, "send.receipt") defer osp.Finish() osp.LogFields(olog.String("ref", hex.EncodeToString(chmsg.Addr))) osp.SetTag("addr", hex.EncodeToString(chmsg.Addr)) @@ -126,6 +124,6 @@ func (s *Storer) sendReceiptMsg(chmsg *chunkMsg) error { return err } to := chmsg.Origin - log.Debug("send receipt", "addr", label(rmsg.Addr), "to", label(to), "self", hex.EncodeToString(s.ps.BaseAddr())) + s.logger.Trace("send receipt", "addr", label(rmsg.Addr), "to", label(to)) return s.ps.Send(to, pssReceiptTopic, msg) } diff --git a/storage/chunker_test.go b/storage/chunker_test.go index 7351c78341..5a41da81e4 100644 --- a/storage/chunker_test.go +++ b/storage/chunker_test.go @@ -43,10 +43,10 @@ type chunkerTester struct { t test } -var mockTag = chunk.NewTag(0, "mock-tag", 0) +var mockTag = chunk.NewTag(context.Background(), 0, "mock-tag", 0) func newTestHasherStore(store ChunkStore, hash string) *hasherStore { - return NewHasherStore(store, MakeHashFunc(hash), false, chunk.NewTag(0, "test-tag", 0)) + return NewHasherStore(store, MakeHashFunc(hash), false, chunk.NewTag(context.Background(), 0, "test-tag", 0)) } func testRandomBrokenData(n int, tester *chunkerTester) { diff --git a/storage/filestore.go b/storage/filestore.go index cb63c43216..834fdd6f6f 100644 --- a/storage/filestore.go +++ b/storage/filestore.go @@ -91,7 +91,7 @@ func (f *FileStore) Retrieve(ctx context.Context, addr Address) (reader *LazyChu isEncrypted = len(addr) > f.hashFunc().Size() tag, err := f.tags.GetFromContext(ctx) if err != nil { - tag = chunk.NewTag(0, "ephemeral-retrieval-tag", 0) + tag = chunk.NewTag(ctx, 0, "ephemeral-retrieval-tag", 0) } getter := NewHasherStore(f.ChunkStore, f.hashFunc, isEncrypted, tag) @@ -108,7 +108,7 @@ func (f *FileStore) Store(ctx context.Context, data io.Reader, size int64, toEnc // of the original request nor the tag with the trie, recalculating the trie hence // loses the tag uid. thus we create an ephemeral tag here for that purpose - tag = chunk.NewTag(0, "", 0) + tag = chunk.NewTag(ctx, 0, "", 0) //return nil, nil, err } putter := NewHasherStore(f.putterStore, f.hashFunc, toEncrypt, tag) @@ -121,7 +121,7 @@ func (f *FileStore) HashSize() int { // GetAllReferences is a public API. This endpoint returns all chunk hashes (only) for a given file func (f *FileStore) GetAllReferences(ctx context.Context, data io.Reader) (addrs AddressCollection, err error) { - tag := chunk.NewTag(0, "ephemeral-tag", 0) //this tag is just a mock ephemeral tag since we don't want to save these results + tag := chunk.NewTag(ctx, 0, "ephemeral-tag", 0) //this tag is just a mock ephemeral tag since we don't want to save these results // create a special kind of putter, which only will store the references putter := &hashExplorer{ diff --git a/storage/hasherstore_test.go b/storage/hasherstore_test.go index 4b6347418f..191a432a66 100644 --- a/storage/hasherstore_test.go +++ b/storage/hasherstore_test.go @@ -44,7 +44,7 @@ func TestHasherStore(t *testing.T) { for _, tt := range tests { chunkStore := NewMapChunkStore() - hasherStore := NewHasherStore(chunkStore, MakeHashFunc(DefaultHash), tt.toEncrypt, chunk.NewTag(0, "test-tag", 2)) + hasherStore := NewHasherStore(chunkStore, MakeHashFunc(DefaultHash), tt.toEncrypt, chunk.NewTag(context.Background(), 0, "test-tag", 2)) // Put two random chunks into the hasherStore chunkData1 := GenerateRandomChunk(int64(tt.chunkLength)).Data() diff --git a/storage/netstore.go b/storage/netstore.go index c3c28b9838..ad59e46edf 100644 --- a/storage/netstore.go +++ b/storage/netstore.go @@ -231,13 +231,9 @@ func (n *NetStore) RemoteFetch(ctx context.Context, req *Request, fi *Fetcher) e for { metrics.GetOrRegisterCounter("remote.fetch.inner", nil).Inc(1) - ctx, osp := spancontext.StartSpan( - ctx, - "remote.fetch") + ctx, osp := spancontext.StartSpan(ctx, "remote.fetch") osp.LogFields(olog.String("ref", ref.String())) - ctx = context.WithValue(ctx, "remote.fetch", osp) - log.Trace("remote.fetch", "ref", ref) currentPeer, err := n.RemoteGet(ctx, req, n.LocalID) diff --git a/storage/pin/pin.go b/storage/pin/pin.go index d9d8a0a087..e3a69a5fdf 100644 --- a/storage/pin/pin.go +++ b/storage/pin/pin.go @@ -140,7 +140,7 @@ func (p *API) PinFiles(addr []byte, isRaw bool, credentials string) error { // Get the file size from the root chunk first 8 bytes hashFunc := storage.MakeHashFunc(storage.DefaultHash) isEncrypted := len(addr) > hashFunc().Size() - getter := storage.NewHasherStore(p.db, hashFunc, isEncrypted, chunk.NewTag(0, "show-chunks-tag", 0)) + getter := storage.NewHasherStore(p.db, hashFunc, isEncrypted, chunk.NewTag(context.Background(), 0, "show-chunks-tag", 0)) chunkData, err := getter.Get(context.Background(), addr) if err != nil { log.Error("Error getting chunk data from localstore.", "Address", hex.EncodeToString(addr)) @@ -365,7 +365,7 @@ func (p *API) walkFile(fileRef storage.Reference, executeFunc func(storage.Refer hashFunc := storage.MakeHashFunc(storage.DefaultHash) hashSize := len(addr) isEncrypted := len(addr) > hashFunc().Size() - getter := storage.NewHasherStore(p.db, hashFunc, isEncrypted, chunk.NewTag(0, "show-chunks-tag", 0)) + getter := storage.NewHasherStore(p.db, hashFunc, isEncrypted, chunk.NewTag(context.Background(), 0, "show-chunks-tag", 0)) // Trigger unwrapping the merkle tree starting from root hash of the file chunkHashesC <- fileRef diff --git a/swarm.go b/swarm.go index 96717501c0..43d873dd7a 100644 --- a/swarm.go +++ b/swarm.go @@ -498,9 +498,6 @@ func (s *Swarm) Stop() error { s.stateStore.Close() } - s.pushSync.Close() - s.storer.Close() - for _, cleanF := range s.cleanupFuncs { err = cleanF() if err != nil { diff --git a/swarm_test.go b/swarm_test.go index 36638dd7d9..89ac6d5238 100644 --- a/swarm_test.go +++ b/swarm_test.go @@ -28,15 +28,14 @@ import ( "testing" "time" - "github.com/ethersphere/swarm/network" - "github.com/ethersphere/swarm/testutil" - "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/rpc" "github.com/ethersphere/swarm/api" + "github.com/ethersphere/swarm/network" "github.com/ethersphere/swarm/sctx" "github.com/ethersphere/swarm/swap" + "github.com/ethersphere/swarm/testutil" ) // TestNewSwarm validates Swarm fields in repsect to the provided configuration. @@ -442,12 +441,13 @@ func testLocalStoreAndRetrieve(t *testing.T, swarm *Swarm, n int, randomData boo rand.Seed(time.Now().UnixNano()) rand.Read(slice) } + ctx := context.Background() dataPut := string(slice) - tag, err := swarm.api.Tags.Create("test-local-store-and-retrieve", 0) + tag, err := swarm.api.Tags.Create(ctx, "test-local-store-and-retrieve", 0) if err != nil { t.Fatal(err) } - ctx := sctx.SetTag(context.Background(), tag.Uid) + ctx = sctx.SetTag(ctx, tag.Uid) k, wait, err := swarm.api.Store(ctx, strings.NewReader(dataPut), int64(len(dataPut)), false) if err != nil { t.Fatal(err) From b229e87576f65db9fab6249b2341716f339a1d5e Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 3 Sep 2019 10:15:57 +0200 Subject: [PATCH 14/22] pushsync: simulation test params for appveyor --- pushsync/simulation_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pushsync/simulation_test.go b/pushsync/simulation_test.go index 0b4ddbac41..6b2d2c3cfe 100644 --- a/pushsync/simulation_test.go +++ b/pushsync/simulation_test.go @@ -50,9 +50,9 @@ var ( ) var ( - nodeCntFlag = flag.Int("nodes", 16, "number of nodes in simulation") - chunkCntFlag = flag.Int("chunks", 16, "number of chunks per upload in simulation") - testCasesFlag = flag.Int("cases", 16, "number of concurrent upload-download cases to test in simulation") + nodeCntFlag = flag.Int("nodes", 4, "number of nodes in simulation") + chunkCntFlag = flag.Int("chunks", 4, "number of chunks per upload in simulation") + testCasesFlag = flag.Int("cases", 4, "number of concurrent upload-download cases to test in simulation") ) // test syncer using pss From 0dbc1db283c2b7d0eeef8c4fe412f6b6b9ff348a Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Tue, 3 Sep 2019 17:44:07 +0300 Subject: [PATCH 15/22] pushsync: asynchronous send in sync forever loop; disabled ordering test --- pushsync/pusher.go | 9 +++++---- pushsync/pusher_test.go | 9 +++++---- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 0442fd3fa3..70d491b93e 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -198,10 +198,11 @@ func (p *Pusher) sync() { metrics.GetOrRegisterCounter("pusher.send-chunk.send-to-sync", nil).Inc(1) // send the chunk and ignore the error - // go func(ch chunk.Chunk) { - if err := p.sendChunkMsg(ch); err != nil { - p.logger.Error("error sending chunk", "addr", ch.Address().Hex(), "err", err) - } + go func(ch chunk.Chunk) { + if err := p.sendChunkMsg(ch); err != nil { + p.logger.Error("error sending chunk", "addr", ch.Address().Hex(), "err", err) + } + }(ch) // handle incoming receipts case addr := <-p.receipts: diff --git a/pushsync/pusher_test.go b/pushsync/pusher_test.go index 1c0d8852b7..e513058b32 100644 --- a/pushsync/pusher_test.go +++ b/pushsync/pusher_test.go @@ -244,10 +244,11 @@ func TestPusher(t *testing.T) { } // check outgoing chunk messages idx := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) - if idx > max { - errf("incorrect order of chunks from db chunk #%d before #%d", idx, max) - return nil - } + // disable ordering test + //if idx > max { + //errf("incorrect order of chunks from db chunk #%d before #%d", idx, max) + //return nil + //} max++ // respond ~ mock storer protocol go func() { From 71436e138f2dc567184252213b58d0ffdd375231 Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 3 Sep 2019 11:11:59 +0200 Subject: [PATCH 16/22] api/http: remove periodicTagTrace --- api/http/server.go | 24 ------------------------ 1 file changed, 24 deletions(-) diff --git a/api/http/server.go b/api/http/server.go index a3e48b2c5d..ce66a06182 100644 --- a/api/http/server.go +++ b/api/http/server.go @@ -46,8 +46,6 @@ import ( "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/storage/feed" "github.com/ethersphere/swarm/storage/pin" - "github.com/opentracing/opentracing-go" - olog "github.com/opentracing/opentracing-go/log" "github.com/rs/cors" ) @@ -1146,25 +1144,3 @@ func (lrw *loggingResponseWriter) WriteHeader(code int) { func isDecryptError(err error) bool { return strings.Contains(err.Error(), api.ErrDecrypt.Error()) } - -// periodicTagTrace queries the tag every 2 seconds and logs its state to the span -func periodicTagTrace(tags *chunk.Tags, tagUID uint32, q chan struct{}, sp opentracing.Span) { - report := func() { - tag, err := tags.Get(tagUID) - if err != nil { - log.Error("error while getting tag", "tagUID", tagUID, "err", err) - } - - sp.LogFields(olog.String("tag state", fmt.Sprintf("split=%d stored=%d seen=%d synced=%d", tag.Get(chunk.StateSplit), tag.Get(chunk.StateStored), tag.Get(chunk.StateSeen), tag.Get(chunk.StateSynced)))) - } - - for { - select { - case <-q: - report() - return - case <-time.After(2 * time.Second): - report() - } - } -} From 096b08f993eb7f208d48d2285240e39d07cbef0a Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 3 Sep 2019 18:03:45 +0200 Subject: [PATCH 17/22] pushsync: close item span at end of roundtrip --- pushsync/pusher.go | 51 ++++++++++++++++++++-------------------------- 1 file changed, 22 insertions(+), 29 deletions(-) diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 70d491b93e..8a6c6a5b29 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -19,7 +19,6 @@ package pushsync import ( "context" "encoding/hex" - "fmt" "time" "github.com/ethereum/go-ethereum/log" @@ -106,7 +105,6 @@ func (p *Pusher) sync() { var chunks <-chan chunk.Chunk var unsubscribe func() var syncedAddrs []storage.Address - var syncedItems []*pushedItem defer close(p.closed) // timer, initially set to 0 to fall through select case on timer.C for initialisation timer := time.NewTimer(0) @@ -138,32 +136,18 @@ func (p *Pusher) sync() { unsubscribe() } - syncedTags := make(map[uint32]int) // set chunk status to synced, insert to db GC index - if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { - panic(fmt.Sprintf("pushsync: error setting chunks to synced: %v", err)) - } - for i, item := range syncedItems { - // increment synced count for the tag if exists - tag := item.tag - if tag != nil { - syncedTags[tag.Uid] = syncedTags[tag.Uid] + 1 - item.span.Finish() + go func() { + if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { + log.Error("pushsync: error setting chunks to synced", "err", err) } + }() + // delete from pushed items + for i := 0; i < len(syncedAddrs); i++ { delete(p.pushed, syncedAddrs[i].Hex()) } - // iterate over tags in this batch - for uid, n := range syncedTags { - tag, _ := p.tags.Get(uid) - tag.IncN(chunk.StateSynced, n) - if tag.Done(chunk.StateSynced) { - p.logger.Debug("closing root span for tag", "taguid", tag.Uid, "tagname", tag.Name) - tag.FinishRootSpan() - } - } // reset synced list syncedAddrs = nil - syncedItems = nil // we don't want to record the first iteration if chunksInBatch != -1 { @@ -221,17 +205,27 @@ func (p *Pusher) sync() { p.logger.Trace("just synced... ignore", "addr", hexaddr) break } + // increment synced count for the tag if exists + tag := item.tag + if tag != nil { + tag.Inc(chunk.StateSynced) + if tag.Done(chunk.StateSynced) { + p.logger.Debug("closing root span for tag", "taguid", tag.Uid, "tagname", tag.Name) + tag.FinishRootSpan() + } + // finish span for pushsync roundtrip, only have this span if we have a tag + item.span.Finish() + } - // calibrate retryInterval based on roundtrip times totalDuration := time.Since(item.firstSentAt) metrics.GetOrRegisterResettingTimer("pusher.chunk.roundtrip", nil).Update(totalDuration) metrics.GetOrRegisterCounter("pusher.receipts.synced", nil).Inc(1) + // calibrate retryInterval based on roundtrip times measurements, average = p.updateRetryInterval(item, measurements, average) // collect synced addresses and corresponding items to do subsequent batch operations syncedAddrs = append(syncedAddrs, addr) - syncedItems = append(syncedItems, item) item.synced = true case <-p.quit: @@ -251,7 +245,7 @@ func (p *Pusher) handleReceiptMsg(msg []byte) error { if err != nil { return err } - p.logger.Trace("Handler", "receipt", label(receipt.Addr), "self", label(p.ps.BaseAddr())) + p.logger.Trace("Handler", "receipt", label(receipt.Addr)) p.pushReceipt(receipt.Addr) return nil } @@ -279,7 +273,7 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { if err != nil { return err } - p.logger.Trace("send chunk", "addr", label(ch.Address()), "self", label(p.ps.BaseAddr())) + p.logger.Trace("send chunk", "addr", label(ch.Address())) metrics.GetOrRegisterResettingTimer("pusher.send.chunk.rlp", nil).UpdateSince(rlpTimer) @@ -321,19 +315,18 @@ func (p *Pusher) needToSync(ch chunk.Chunk) bool { _, span := spancontext.StartSpan(tag.Context(), "chunk.sent") span.LogFields(olog.String("ref", hexaddr)) span.SetTag("addr", hexaddr) - item.span = span } // remember the item p.pushed[hexaddr] = item if p.ps.IsClosestTo(addr) { - p.logger.Trace("self is closest to ref: push receipt locally", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) + p.logger.Trace("self is closest to ref: push receipt locally", "ref", hexaddr) item.shortcut = true go p.pushReceipt(addr) return false } - p.logger.Trace("self is not the closest to ref: send chunk to neighbourhood", "ref", hexaddr, "self", hex.EncodeToString(p.ps.BaseAddr())) + p.logger.Trace("self is not the closest to ref: send chunk to neighbourhood", "ref", hexaddr) } return true } From cd49ab4dae4b1f27aa58e78dadcb0831456998cc Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 3 Sep 2019 18:11:59 +0200 Subject: [PATCH 18/22] pushsync: amend pusher test, remove loopback sync option --- pushsync/protocol_test.go | 2 +- pushsync/pusher_test.go | 49 +++++++++++---------------------------- 2 files changed, 14 insertions(+), 37 deletions(-) diff --git a/pushsync/protocol_test.go b/pushsync/protocol_test.go index e00db4bc62..3b9a39fb7d 100644 --- a/pushsync/protocol_test.go +++ b/pushsync/protocol_test.go @@ -57,7 +57,7 @@ func TestProtocol(t *testing.T) { sent := &sync.Map{} store := &sync.Map{} // mock pubsub messenger - lb := newLoopBack(true) + lb := newLoopBack() // set up a number of storers storers := make([]*Storer, storerCnt) diff --git a/pushsync/pusher_test.go b/pushsync/pusher_test.go index e513058b32..0e2aa3ad76 100644 --- a/pushsync/pusher_test.go +++ b/pushsync/pusher_test.go @@ -68,13 +68,11 @@ func (tps *testPubSub) IsClosestTo(addr []byte) bool { // loopback implements PubSub as a central subscription engine, // ie a msg sent is received by all handlers registered for the topic type loopBack struct { - async bool handlers map[string][]func(msg []byte, p *p2p.Peer) error } -func newLoopBack(async bool) *loopBack { +func newLoopBack() *loopBack { return &loopBack{ - async: async, handlers: make(map[string][]func(msg []byte, p *p2p.Peer) error), } } @@ -88,13 +86,7 @@ func (lb *loopBack) Register(topic string, _ bool, handler func(msg []byte, p *p // Send publishes a msg with a topic and directly calls registered handlers with // that topic func (lb *loopBack) Send(to []byte, topic string, msg []byte) error { - if lb.async { - go func() { - if !delayResponse() { - return - } - lb.send(to, topic, msg) - }() + if !delayResponse() { return nil } return lb.send(to, topic, msg) @@ -233,9 +225,8 @@ func TestPusher(t *testing.T) { } } - lb := newLoopBack(false) + lb := newLoopBack() - max := 0 // the highest index sent so far respond := func(msg []byte, _ *p2p.Peer) error { chmsg, err := decodeChunkMsg(msg) if err != nil { @@ -244,31 +235,17 @@ func TestPusher(t *testing.T) { } // check outgoing chunk messages idx := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) - // disable ordering test - //if idx > max { - //errf("incorrect order of chunks from db chunk #%d before #%d", idx, max) - //return nil - //} - max++ // respond ~ mock storer protocol - go func() { - receipt := &receiptMsg{Addr: chmsg.Addr} - rmsg, err := rlp.EncodeToBytes(receipt) - if err != nil { - errf("error encoding receipt message: %v", err) - } - log.Debug("chunk sent", "idx", idx) - // random delay to allow retries - if !delayResponse() { - log.Debug("chunk/receipt lost", "idx", idx) - return - } - log.Debug("store chunk, send receipt", "idx", idx) - err = lb.Send(chmsg.Origin, pssReceiptTopic, rmsg) - if err != nil { - errf("error sending receipt message: %v", err) - } - }() + receipt := &receiptMsg{Addr: chmsg.Addr} + rmsg, err := rlp.EncodeToBytes(receipt) + if err != nil { + errf("error encoding receipt message: %v", err) + } + log.Debug("store chunk, send receipt", "idx", idx) + err = lb.Send(chmsg.Origin, pssReceiptTopic, rmsg) + if err != nil { + errf("error sending receipt message: %v", err) + } return nil } // register the respond function From 55a4758bab32f9e45c116237f77f63a48f749936 Mon Sep 17 00:00:00 2001 From: zelig Date: Tue, 3 Sep 2019 18:23:27 +0200 Subject: [PATCH 19/22] pushsync: if no new items set timer to half a second --- pushsync/pusher.go | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 8a6c6a5b29..7d4737271e 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -136,16 +136,15 @@ func (p *Pusher) sync() { unsubscribe() } - // set chunk status to synced, insert to db GC index - go func() { - if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { - log.Error("pushsync: error setting chunks to synced", "err", err) - } - }() // delete from pushed items for i := 0; i < len(syncedAddrs); i++ { delete(p.pushed, syncedAddrs[i].Hex()) } + // set chunk status to synced, insert to db GC index + if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { + log.Error("pushsync: error setting chunks to synced", "err", err) + } + // reset synced list syncedAddrs = nil @@ -169,7 +168,11 @@ func (p *Pusher) sync() { // if no more, set to nil, reset timer to 0 to finalise batch immediately if !more { chunks = nil - timer.Reset(0) + var dur time.Duration + if chunksInBatch == 0 { + dur = 500 * time.Millisecond + } + timer.Reset(dur) break } From 048ca03c33972cd9b34cff8c4f457ada9837b255 Mon Sep 17 00:00:00 2001 From: zelig Date: Mon, 9 Sep 2019 09:12:37 +0200 Subject: [PATCH 20/22] pushsync: address PR review feedback --- chunk/tags.go | 2 +- pushsync/protocol_test.go | 36 +++++++++++++++++++----------------- pushsync/pusher.go | 2 +- pushsync/simulation_test.go | 30 +++++++++--------------------- pushsync/storer.go | 6 +++--- storage/netstore.go | 31 +++++++++++++++++++++++++++++-- 6 files changed, 62 insertions(+), 45 deletions(-) diff --git a/chunk/tags.go b/chunk/tags.go index 2697e3f0cf..f965ad8aa0 100644 --- a/chunk/tags.go +++ b/chunk/tags.go @@ -44,7 +44,7 @@ func NewTags() *Tags { // it returns an error if the tag with this name already exists func (ts *Tags) Create(ctx context.Context, s string, total int64) (*Tag, error) { t := &Tag{ - Uid: uint32(rand.Int31()), + Uid: rand.Uint32(), Name: s, StartedAt: time.Now(), Total: total, diff --git a/pushsync/protocol_test.go b/pushsync/protocol_test.go index 3b9a39fb7d..86a370253e 100644 --- a/pushsync/protocol_test.go +++ b/pushsync/protocol_test.go @@ -84,28 +84,30 @@ func TestProtocol(t *testing.T) { synced := make(map[int]int) for { select { + // receive indexes on synced channel when a chunk is set as synced case idx := <-tp.synced: n := synced[idx] synced[idx] = n + 1 - if len(synced) == chunkCnt { - expTotal := int64(chunkCnt / tagCnt) - checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) - for i := uint64(0); i < uint64(chunkCnt); i++ { - if n := synced[int(i)]; n != 1 { - t.Fatalf("expected to receive exactly 1 receipt for chunk %v, got %v", i, n) - } - v, ok := store.Load(i) - if !ok { - t.Fatalf("chunk %v not stored", i) - } - if cnt := *(v.(*uint32)); cnt < uint32(storerCnt) { - t.Fatalf("chunk %v expected to be saved at least %v times, got %v", i, storerCnt, cnt) - } - } - return - } case <-time.After(timeout): t.Fatalf("timeout waiting for all chunks to be synced") } + // all chunks set as synced + if len(synced) == chunkCnt { + expTotal := int64(chunkCnt / tagCnt) + checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) + for i := uint64(0); i < uint64(chunkCnt); i++ { + if n := synced[int(i)]; n != 1 { + t.Fatalf("expected to receive exactly 1 receipt for chunk %v, got %v", i, n) + } + v, ok := store.Load(i) + if !ok { + t.Fatalf("chunk %v not stored", i) + } + if cnt := *(v.(*uint32)); cnt < uint32(storerCnt) { + t.Fatalf("chunk %v expected to be saved at least %v times, got %v", i, storerCnt, cnt) + } + } + return + } } } diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 7d4737271e..82aa42f15c 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -81,7 +81,7 @@ func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { pushed: make(map[string]*pushedItem), receipts: make(chan []byte), ps: ps, - logger: log.New("self", hex.EncodeToString(ps.BaseAddr())), + logger: log.New("self", label(ps.BaseAddr())), retryInterval: 100 * time.Millisecond, } go p.sync() diff --git a/pushsync/simulation_test.go b/pushsync/simulation_test.go index 6b2d2c3cfe..fe7692a08c 100644 --- a/pushsync/simulation_test.go +++ b/pushsync/simulation_test.go @@ -42,6 +42,7 @@ import ( "github.com/ethersphere/swarm/state" "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/storage/localstore" + "golang.org/x/sync/errgroup" ) var ( @@ -118,7 +119,7 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, testcases int, sf simulation.Servic if result.Error != nil { return fmt.Errorf("simulation error: %v", result.Error) } - log.Error("simulation", "duration", time.Since(start)) + log.Info("simulation", "duration", time.Since(start)) return nil } @@ -152,13 +153,12 @@ func uploadAndDownload(ctx context.Context, sim *simulation.Simulation, nodeCnt, // wait till pushsync is done syncTimeout := 30 * time.Second sctx, cancel := context.WithTimeout(ctx, syncTimeout) + defer cancel() err = tag.WaitTillDone(sctx, chunk.StateSynced) if err != nil { log.Debug("tag", "tag", tag) - cancel() return fmt.Errorf("error waiting syncing: %v", err) } - cancel() log.Debug("downloading", "peer", did, "chunks", chunkCnt, "tagname", tagname) netstore := sim.MustNodeItem(did, bucketKeyNetStore).(*storage.NetStore) @@ -197,7 +197,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } - // // streamer for retrieval + // streamer for retrieval delivery := stream.NewDelivery(kad, netStore) netStore.RemoteGet = delivery.RequestFromPeers @@ -270,26 +270,14 @@ func upload(ctx context.Context, store Store, tags *chunk.Tags, tagname string, } func download(ctx context.Context, store *storage.NetStore, addrs []storage.Address) error { - errc := make(chan error) + var g errgroup.Group for _, addr := range addrs { - go func(addr storage.Address) { + addr := addr + g.Go(func() error { _, err := store.Get(ctx, chunk.ModeGetRequest, storage.NewRequest(addr)) log.Debug("Get", "addr", hex.EncodeToString(addr[:]), "err", err) - select { - case errc <- err: - case <-ctx.Done(): - } - }(addr) - } - i := 0 - for err := range errc { - if err != nil { return err - } - i++ - if i == len(addrs) { - break - } + }) } - return nil + return g.Wait() } diff --git a/pushsync/storer.go b/pushsync/storer.go index 77d14f065f..c42ae10701 100644 --- a/pushsync/storer.go +++ b/pushsync/storer.go @@ -44,7 +44,7 @@ type Storer struct { } // NewStorer constructs a Storer -// Storer run storer nodes to handle the reception of push-synced chunks +// Storer runs on storer nodes to handle the reception of push-synced chunks // that fall within their area of responsibility. // The protocol makes sure that // - the chunks are stored and synced to their nearest neighbours and @@ -54,7 +54,7 @@ func NewStorer(store Store, ps PubSub) *Storer { s := &Storer{ store: store, ps: ps, - logger: log.New("self", hex.EncodeToString(ps.BaseAddr())), + logger: log.New("self", label(ps.BaseAddr())), } s.deregister = ps.Register(pssChunkTopic, true, func(msg []byte, _ *p2p.Peer) error { return s.handleChunkMsg(msg) @@ -99,7 +99,7 @@ func (s *Storer) processChunkMsg(ctx context.Context, chmsg *chunkMsg) error { // if self is closest peer then send back a receipt if s.ps.IsClosestTo(chmsg.Addr) { - s.logger.Trace("self is closest to ref", "ref", hex.EncodeToString(chmsg.Addr)) + s.logger.Trace("self is closest to ref", "ref", label(chmsg.Addr)) return s.sendReceiptMsg(ctx, chmsg) } return nil diff --git a/storage/netstore.go b/storage/netstore.go index ad59e46edf..b77ba0302f 100644 --- a/storage/netstore.go +++ b/storage/netstore.go @@ -24,15 +24,23 @@ import ( "sync" "time" +<<<<<<< HEAD "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/p2p/enode" +======= +>>>>>>> pushsync: address PR review feedback "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/network/timeouts" "github.com/ethersphere/swarm/spancontext" lru "github.com/hashicorp/golang-lru" +<<<<<<< HEAD +======= + "github.com/ethereum/go-ethereum/metrics" + "github.com/ethereum/go-ethereum/p2p/enode" +>>>>>>> pushsync: address PR review feedback olog "github.com/opentracing/opentracing-go/log" "github.com/syndtr/goleveldb/leveldb" "golang.org/x/sync/singleflight" @@ -112,7 +120,11 @@ func (n *NetStore) Put(ctx context.Context, mode chunk.ModePut, chs ...Chunk) ([ defer n.putMu.Unlock() for i, ch := range chs { +<<<<<<< HEAD n.logger.Trace("netstore.put", "index", i, "ref", ch.Address().String(), "mode", mode) +======= + log.Trace("netstore.put", "index", i, "ref", ch.Address().String(), "mode", mode) +>>>>>>> pushsync: address PR review feedback } // put the chunk to the localstore, there should be no error exist, err := n.Store.Put(ctx, mode, chs...) @@ -158,6 +170,11 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C ref := req.Addr +<<<<<<< HEAD +======= + log.Trace("netstore.get", "ref", ref.String()) + +>>>>>>> pushsync: address PR review feedback ch, err := n.Store.Get(ctx, mode, ref) if err != nil { // TODO: fix comparison - we should be comparing against leveldb.ErrNotFound, this error should be wrapped. @@ -165,7 +182,11 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C n.logger.Error("localstore get error", "err", err) } +<<<<<<< HEAD n.logger.Trace("netstore.chunk-not-in-localstore", "ref", ref.String()) +======= + log.Trace("netstore.chunk-not-in-localstore", "ref", ref.String()) +>>>>>>> pushsync: address PR review feedback v, err, _ := n.requestGroup.Do(ref.String(), func() (interface{}, error) { // currently we issue a retrieve request if a fetcher @@ -203,7 +224,11 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C c := v.(Chunk) +<<<<<<< HEAD n.logger.Trace("netstore.singleflight returned", "ref", ref.String(), "err", err) +======= + log.Trace("netstore.singleflight returned", "ref", ref.String(), "err", err) +>>>>>>> pushsync: address PR review feedback return c, nil } @@ -231,9 +256,11 @@ func (n *NetStore) RemoteFetch(ctx context.Context, req *Request, fi *Fetcher) e for { metrics.GetOrRegisterCounter("remote.fetch.inner", nil).Inc(1) - ctx, osp := spancontext.StartSpan(ctx, "remote.fetch") + ctx, osp := spancontext.StartSpan( + ctx, + "remote.fetch") osp.LogFields(olog.String("ref", ref.String())) - ctx = context.WithValue(ctx, "remote.fetch", osp) + log.Trace("remote.fetch", "ref", ref) currentPeer, err := n.RemoteGet(ctx, req, n.LocalID) From 1eb077ec56d9bc21e828315a42336c4fff828698 Mon Sep 17 00:00:00 2001 From: zelig Date: Thu, 12 Sep 2019 15:02:02 +0200 Subject: [PATCH 21/22] pushsync, testutil: address review comments - changed order of select cases - have Tests on top followed by helpers - add sent,synced check to testutil.CheckTag - add timeout to close wait - adapt to testutil.Init() - length protection to label helper - resolve rebase conflicts --- chunk/testing/tag.go | 10 +++ pushsync/protocol.go | 6 +- pushsync/protocol_test.go | 36 ++++---- pushsync/pusher.go | 87 +++++++++--------- pushsync/pusher_test.go | 175 +++++++++++++++++------------------- pushsync/simulation_test.go | 41 ++++----- storage/netstore.go | 27 ------ 7 files changed, 181 insertions(+), 201 deletions(-) diff --git a/chunk/testing/tag.go b/chunk/testing/tag.go index d4f34c07f7..0dcfb20d87 100644 --- a/chunk/testing/tag.go +++ b/chunk/testing/tag.go @@ -43,6 +43,16 @@ func CheckTag(t *testing.T, tag *chunk.Tag, split, stored, seen, sent, synced, t t.Fatalf("mismatch stored chunks, got %d want %d", tStored, stored) } + tSent := tag.Get(chunk.StateSent) + if tStored != stored { + t.Fatalf("mismatch sent chunks, got %d want %d", tSent, sent) + } + + tSynced := tag.Get(chunk.StateSynced) + if tStored != stored { + t.Fatalf("mismatch synced chunks, got %d want %d", tSynced, synced) + } + tTotal := tag.TotalCounter() if tTotal != total { t.Fatalf("mismatch total chunks, got %d want %d", tTotal, total) diff --git a/pushsync/protocol.go b/pushsync/protocol.go index 41b00e99a4..1a1b700948 100644 --- a/pushsync/protocol.go +++ b/pushsync/protocol.go @@ -81,5 +81,9 @@ func newNonce() []byte { } func label(b []byte) string { - return hexutil.Encode(b[:8]) + l := len(b) + if l > 8 { + l = 8 + } + return hexutil.Encode(b[:l]) } diff --git a/pushsync/protocol_test.go b/pushsync/protocol_test.go index 86a370253e..b51c23ffb6 100644 --- a/pushsync/protocol_test.go +++ b/pushsync/protocol_test.go @@ -28,24 +28,6 @@ import ( "github.com/ethersphere/swarm/log" ) -type testStore struct { - store *sync.Map -} - -func (t *testStore) Put(_ context.Context, _ chunk.ModePut, chs ...chunk.Chunk) ([]bool, error) { - exists := make([]bool, len(chs)) - for i, ch := range chs { - idx := binary.BigEndian.Uint64(ch.Address()[:8]) - var storedCnt uint32 = 1 - if v, loaded := t.store.LoadOrStore(idx, &storedCnt); loaded { - atomic.AddUint32(v.(*uint32), 1) - exists[i] = loaded - } - log.Debug("testStore put", "idx", idx) - } - return exists, nil -} - // TestProtocol tests the push sync protocol // push syncer node communicate with storers via mock loopback PubSub func TestProtocol(t *testing.T) { @@ -111,3 +93,21 @@ func TestProtocol(t *testing.T) { } } } + +type testStore struct { + store *sync.Map +} + +func (t *testStore) Put(_ context.Context, _ chunk.ModePut, chs ...chunk.Chunk) ([]bool, error) { + exists := make([]bool, len(chs)) + for i, ch := range chs { + idx := binary.BigEndian.Uint64(ch.Address()[:8]) + var storedCnt uint32 = 1 + if v, loaded := t.store.LoadOrStore(idx, &storedCnt); loaded { + atomic.AddUint32(v.(*uint32), 1) + exists[i] = loaded + } + log.Debug("testStore put", "idx", idx) + } + return exists, nil +} diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 82aa42f15c..91a6aef832 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -51,7 +51,7 @@ type Pusher struct { receipts chan []byte // channel to receive receipts ps PubSub // PubSub interface to send chunks and receive receipts logger log.Logger // custom logger - retryInterval time.Duration // dynamically adjusted time interval between retriess + retryInterval time.Duration // dynamically adjusted time interval between retries } const maxMeasurements = 20000 @@ -67,7 +67,7 @@ type pushedItem struct { span opentracing.Span // roundtrip span } -// NewPusher contructs a Pusher and starts up the push sync protocol +// NewPusher constructs a Pusher and starts up the push sync protocol // takes // - a DB interface to subscribe to push sync index to allow iterating over recently stored chunks // - a pubsub interface to send chunks and receive statements of custody @@ -91,7 +91,11 @@ func NewPusher(store DB, ps PubSub, tags *chunk.Tags) *Pusher { // Close closes the pusher func (p *Pusher) Close() { close(p.quit) - <-p.closed + select { + case <-p.closed: + case <-time.After(3 * time.Second): + log.Error("timeout closing pusher") + } } // sync starts a forever loop that pushes chunks to their neighbourhood @@ -125,44 +129,6 @@ func (p *Pusher) sync() { for { select { - - // retry interval timer triggers starting from new - case <-timer.C: - // initially timer is set to go off as well as every time we hit the end of push index - // so no wait for retryInterval needed to set items synced - metrics.GetOrRegisterCounter("pusher.subscribe-push", nil).Inc(1) - // if subscribe was running, stop it - if unsubscribe != nil { - unsubscribe() - } - - // delete from pushed items - for i := 0; i < len(syncedAddrs); i++ { - delete(p.pushed, syncedAddrs[i].Hex()) - } - // set chunk status to synced, insert to db GC index - if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { - log.Error("pushsync: error setting chunks to synced", "err", err) - } - - // reset synced list - syncedAddrs = nil - - // we don't want to record the first iteration - if chunksInBatch != -1 { - // this measurement is not a timer, but we want a histogram, so it fits the data structure - metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.hist", nil).Update(time.Duration(chunksInBatch)) - metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.time", nil).UpdateSince(batchStartTime) - metrics.GetOrRegisterCounter("pusher.subscribe-push.chunks-in-batch", nil).Inc(int64(chunksInBatch)) - } - chunksInBatch = 0 - batchStartTime = time.Now() - - // and start iterating on Push index from the beginning - chunks, unsubscribe = p.store.SubscribePush(ctx) - // reset timer to go off after retryInterval - timer.Reset(p.retryInterval) - // handle incoming chunks case ch, more := <-chunks: // if no more, set to nil, reset timer to 0 to finalise batch immediately @@ -231,6 +197,43 @@ func (p *Pusher) sync() { syncedAddrs = append(syncedAddrs, addr) item.synced = true + // retry interval timer triggers starting from new + case <-timer.C: + // initially timer is set to go off as well as every time we hit the end of push index + // so no wait for retryInterval needed to set items synced + metrics.GetOrRegisterCounter("pusher.subscribe-push", nil).Inc(1) + // if subscribe was running, stop it + if unsubscribe != nil { + unsubscribe() + } + + // delete from pushed items + for i := 0; i < len(syncedAddrs); i++ { + delete(p.pushed, syncedAddrs[i].Hex()) + } + // set chunk status to synced, insert to db GC index + if err := p.store.Set(ctx, chunk.ModeSetSync, syncedAddrs...); err != nil { + log.Error("pushsync: error setting chunks to synced", "err", err) + } + + // reset synced list + syncedAddrs = nil + + // we don't want to record the first iteration + if chunksInBatch != -1 { + // this measurement is not a timer, but we want a histogram, so it fits the data structure + metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.hist", nil).Update(time.Duration(chunksInBatch)) + metrics.GetOrRegisterResettingTimer("pusher.subscribe-push.chunks-in-batch.time", nil).UpdateSince(batchStartTime) + metrics.GetOrRegisterCounter("pusher.subscribe-push.chunks-in-batch", nil).Inc(int64(chunksInBatch)) + } + chunksInBatch = 0 + batchStartTime = time.Now() + + // and start iterating on Push index from the beginning + chunks, unsubscribe = p.store.SubscribePush(ctx) + // reset timer to go off after retryInterval + timer.Reset(p.retryInterval) + case <-p.quit: if unsubscribe != nil { unsubscribe() @@ -268,7 +271,7 @@ func (p *Pusher) sendChunkMsg(ch chunk.Chunk) error { cmsg := &chunkMsg{ Origin: p.ps.BaseAddr(), - Addr: ch.Address()[:], + Addr: ch.Address(), Data: ch.Data(), Nonce: newNonce(), } diff --git a/pushsync/pusher_test.go b/pushsync/pusher_test.go index 0e2aa3ad76..f032b4d6f3 100644 --- a/pushsync/pusher_test.go +++ b/pushsync/pusher_test.go @@ -20,7 +20,6 @@ import ( "context" "encoding/binary" "encoding/hex" - "flag" "fmt" "math/rand" "sync" @@ -32,19 +31,94 @@ import ( "github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/rlp" "github.com/ethersphere/swarm/chunk" + chunktesting "github.com/ethersphere/swarm/chunk/testing" "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/testutil" - colorable "github.com/mattn/go-colorable" -) - -var ( - loglevel = flag.Int("loglevel", 0, "verbosity of logs") ) func init() { - flag.Parse() - log.PrintOrigins(true) - log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(*loglevel), log.StreamHandler(colorable.NewColorableStderr(), log.TerminalFormat(true)))) + testutil.Init() +} + +// TestPusher tests the correct behaviour of Pusher +// in the context of inserting n chunks +// receipt response model: the pushed chunk's receipt is sent back +// after a random delay +// The test checks: +// - if sync function is called on chunks in order of insertion (FIFO) +// - already synced chunks are not resynced +// - if no more data inserted, the db is emptied shortly +func TestPusher(t *testing.T) { + timeout := 10 * time.Second + chunkCnt := 1024 + tagCnt := 4 + + errc := make(chan error) + sent := &sync.Map{} + synced := make(map[int]int) + quit := make(chan struct{}) + defer close(quit) + + errf := func(s string, vals ...interface{}) { + select { + case errc <- fmt.Errorf(s, vals...): + case <-quit: + } + } + + lb := newLoopBack() + + respond := func(msg []byte, _ *p2p.Peer) error { + chmsg, err := decodeChunkMsg(msg) + if err != nil { + errf("error decoding chunk message: %v", err) + return nil + } + // check outgoing chunk messages + idx := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) + // respond ~ mock storer protocol + receipt := &receiptMsg{Addr: chmsg.Addr} + rmsg, err := rlp.EncodeToBytes(receipt) + if err != nil { + errf("error encoding receipt message: %v", err) + } + log.Debug("store chunk, send receipt", "idx", idx) + err = lb.Send(chmsg.Origin, pssReceiptTopic, rmsg) + if err != nil { + errf("error sending receipt message: %v", err) + } + return nil + } + // register the respond function + lb.Register(pssChunkTopic, false, respond) + tags, tagIDs := setupTags(chunkCnt, tagCnt) + // construct the mock push sync index iterator + tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) + // start push syncing in a go routine + p := NewPusher(tp, &testPubSub{lb, func([]byte) bool { return false }}, tags) + defer p.Close() + // collect synced chunks until all chunks synced + // wait on errc for errors on any thread + // otherwise time out + for { + select { + case i := <-tp.synced: + n := synced[i] + synced[i] = n + 1 + if len(synced) == chunkCnt { + expTotal := int64(chunkCnt / tagCnt) + checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) + return + } + case err := <-errc: + if err != nil { + t.Fatal(err) + } + case <-time.After(timeout): + t.Fatalf("timeout waiting for all chunks to be synced") + } + } + } type testPubSub struct { @@ -199,87 +273,6 @@ func delayResponse() bool { return delay < retentionLimit } -// TestPusher tests the correct behaviour of Pusher -// in the context of inserting n chunks -// receipt response model: the pushed chunk's receipt is sent back -// after a random delay -// The test checks: -// - if sync function is called on chunks in order of insertion (FIFO) -// - already synced chunks are not resynced -// - if no more data inserted, the db is emptied shortly -func TestPusher(t *testing.T) { - timeout := 10 * time.Second - chunkCnt := 1024 - tagCnt := 4 - - errc := make(chan error) - sent := &sync.Map{} - synced := make(map[int]int) - quit := make(chan struct{}) - defer close(quit) - - errf := func(s string, vals ...interface{}) { - select { - case errc <- fmt.Errorf(s, vals...): - case <-quit: - } - } - - lb := newLoopBack() - - respond := func(msg []byte, _ *p2p.Peer) error { - chmsg, err := decodeChunkMsg(msg) - if err != nil { - errf("error decoding chunk message: %v", err) - return nil - } - // check outgoing chunk messages - idx := int(binary.BigEndian.Uint64(chmsg.Addr[:8])) - // respond ~ mock storer protocol - receipt := &receiptMsg{Addr: chmsg.Addr} - rmsg, err := rlp.EncodeToBytes(receipt) - if err != nil { - errf("error encoding receipt message: %v", err) - } - log.Debug("store chunk, send receipt", "idx", idx) - err = lb.Send(chmsg.Origin, pssReceiptTopic, rmsg) - if err != nil { - errf("error sending receipt message: %v", err) - } - return nil - } - // register the respond function - lb.Register(pssChunkTopic, false, respond) - tags, tagIDs := setupTags(chunkCnt, tagCnt) - // construct the mock push sync index iterator - tp := newTestPushSyncIndex(chunkCnt, tagIDs, tags, sent) - // start push syncing in a go routine - p := NewPusher(tp, &testPubSub{lb, func([]byte) bool { return false }}, tags) - defer p.Close() - // collect synced chunks until all chunks synced - // wait on errc for errors on any thread - // otherwise time out - for { - select { - case i := <-tp.synced: - n := synced[i] - synced[i] = n + 1 - if len(synced) == chunkCnt { - expTotal := int64(chunkCnt / tagCnt) - checkTags(t, expTotal, tagIDs[:tagCnt-1], tags) - return - } - case err := <-errc: - if err != nil { - t.Fatal(err) - } - case <-time.After(timeout): - t.Fatalf("timeout waiting for all chunks to be synced") - } - } - -} - // setupTags constructs tags object create tagCnt - 1 tags // the sequential fake chunk i will be tagged with i%tagCnt func setupTags(chunkCnt, tagCnt int) (tags *chunk.Tags, tagIDs []uint32) { @@ -311,6 +304,6 @@ func checkTags(t *testing.T, expTotal int64, tagIDs []uint32, tags *chunk.Tags) t.Fatalf("error waiting for syncing on tag %v: %v", tag.Uid, err) } - testutil.CheckTag(t, tag, 0, expTotal, 0, expTotal, expTotal, expTotal) + chunktesting.CheckTag(t, tag, 0, expTotal, 0, expTotal, expTotal, expTotal) } } diff --git a/pushsync/simulation_test.go b/pushsync/simulation_test.go index fe7692a08c..bf50748cd4 100644 --- a/pushsync/simulation_test.go +++ b/pushsync/simulation_test.go @@ -33,13 +33,13 @@ import ( "github.com/ethereum/go-ethereum/node" "github.com/ethereum/go-ethereum/p2p" "github.com/ethereum/go-ethereum/p2p/simulations/adapters" + "github.com/ethereum/go-ethereum/rpc" "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/log" "github.com/ethersphere/swarm/network" + "github.com/ethersphere/swarm/network/retrieval" "github.com/ethersphere/swarm/network/simulation" - "github.com/ethersphere/swarm/network/stream" "github.com/ethersphere/swarm/pss" - "github.com/ethersphere/swarm/state" "github.com/ethersphere/swarm/storage" "github.com/ethersphere/swarm/storage/localstore" "golang.org/x/sync/errgroup" @@ -84,7 +84,7 @@ func testSyncerWithPubSub(nodeCnt, chunkCnt, testcases int, sf simulation.Servic ctx := context.Background() snapCtx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() - err := sim.UploadSnapshot(snapCtx, filepath.Join("../network/stream/testing", fmt.Sprintf("snapshot_%d.json", nodeCnt))) + err := sim.UploadSnapshot(snapCtx, filepath.Join("../network/stream/testdata", fmt.Sprintf("snapshot_%d.json", nodeCnt))) if err != nil { return fmt.Errorf("error while loading snapshot: %v", err) } @@ -183,7 +183,7 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } // setup netstore - netStore := storage.NewNetStore(lstore, n.ID()) + netStore := storage.NewNetStore(lstore, addr.Over(), n.ID()) // setup pss kadParams := network.NewKadParams() @@ -197,15 +197,9 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic return nil, nil, err } - // streamer for retrieval - delivery := stream.NewDelivery(kad, netStore) - netStore.RemoteGet = delivery.RequestFromPeers - bucket.Store(bucketKeyNetStore, netStore) - // set up syncer - noSyncing := &stream.RegistryOptions{Syncing: stream.SyncingDisabled, SyncUpdateDelay: 50 * time.Millisecond} - r := stream.NewRegistry(addr.ID(), delivery, netStore, state.NewInmemoryStore(), noSyncing, nil) + r := retrieval.New(kad, netStore, kad.BaseAddr()) pubSub := pss.NewPubSub(ps) // setup pusher @@ -218,34 +212,37 @@ func newServiceFunc(ctx *adapters.ServiceContext, bucket *sync.Map) (node.Servic cleanup := func() { p.Close() s.Close() - r.Close() netStore.Close() os.RemoveAll(dir) } - return &StreamerAndPss{r, ps}, cleanup, nil + return &RetrievalAndPss{r, ps}, cleanup, nil } // implements the node.Service interface -type StreamerAndPss struct { - *stream.Registry - pss *pss.Pss +type RetrievalAndPss struct { + retrieval *retrieval.Retrieval + pss *pss.Pss +} + +func (s *RetrievalAndPss) APIs() []rpc.API { + return nil } -func (s *StreamerAndPss) Protocols() []p2p.Protocol { - return append(s.Registry.Protocols(), s.pss.Protocols()...) +func (s *RetrievalAndPss) Protocols() []p2p.Protocol { + return append(s.retrieval.Protocols(), s.pss.Protocols()...) } -func (s *StreamerAndPss) Start(srv *p2p.Server) error { - err := s.Registry.Start(srv) +func (s *RetrievalAndPss) Start(srv *p2p.Server) error { + err := s.retrieval.Start(srv) if err != nil { return err } return s.pss.Start(srv) } -func (s *StreamerAndPss) Stop() error { - err := s.Registry.Stop() +func (s *RetrievalAndPss) Stop() error { + err := s.retrieval.Stop() if err != nil { return err } diff --git a/storage/netstore.go b/storage/netstore.go index b77ba0302f..b5d1d4d3f2 100644 --- a/storage/netstore.go +++ b/storage/netstore.go @@ -24,23 +24,13 @@ import ( "sync" "time" -<<<<<<< HEAD "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/p2p/enode" - -======= ->>>>>>> pushsync: address PR review feedback "github.com/ethersphere/swarm/chunk" "github.com/ethersphere/swarm/network/timeouts" "github.com/ethersphere/swarm/spancontext" lru "github.com/hashicorp/golang-lru" - -<<<<<<< HEAD -======= - "github.com/ethereum/go-ethereum/metrics" - "github.com/ethereum/go-ethereum/p2p/enode" ->>>>>>> pushsync: address PR review feedback olog "github.com/opentracing/opentracing-go/log" "github.com/syndtr/goleveldb/leveldb" "golang.org/x/sync/singleflight" @@ -120,11 +110,7 @@ func (n *NetStore) Put(ctx context.Context, mode chunk.ModePut, chs ...Chunk) ([ defer n.putMu.Unlock() for i, ch := range chs { -<<<<<<< HEAD n.logger.Trace("netstore.put", "index", i, "ref", ch.Address().String(), "mode", mode) -======= - log.Trace("netstore.put", "index", i, "ref", ch.Address().String(), "mode", mode) ->>>>>>> pushsync: address PR review feedback } // put the chunk to the localstore, there should be no error exist, err := n.Store.Put(ctx, mode, chs...) @@ -170,11 +156,6 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C ref := req.Addr -<<<<<<< HEAD -======= - log.Trace("netstore.get", "ref", ref.String()) - ->>>>>>> pushsync: address PR review feedback ch, err := n.Store.Get(ctx, mode, ref) if err != nil { // TODO: fix comparison - we should be comparing against leveldb.ErrNotFound, this error should be wrapped. @@ -182,11 +163,7 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C n.logger.Error("localstore get error", "err", err) } -<<<<<<< HEAD n.logger.Trace("netstore.chunk-not-in-localstore", "ref", ref.String()) -======= - log.Trace("netstore.chunk-not-in-localstore", "ref", ref.String()) ->>>>>>> pushsync: address PR review feedback v, err, _ := n.requestGroup.Do(ref.String(), func() (interface{}, error) { // currently we issue a retrieve request if a fetcher @@ -224,11 +201,7 @@ func (n *NetStore) Get(ctx context.Context, mode chunk.ModeGet, req *Request) (C c := v.(Chunk) -<<<<<<< HEAD n.logger.Trace("netstore.singleflight returned", "ref", ref.String(), "err", err) -======= - log.Trace("netstore.singleflight returned", "ref", ref.String(), "err", err) ->>>>>>> pushsync: address PR review feedback return c, nil } From 68903b5792dc0083ad508e5d99c5d295c5c5a344 Mon Sep 17 00:00:00 2001 From: Anton Evangelatov Date: Tue, 17 Sep 2019 15:43:25 +0200 Subject: [PATCH 22/22] pss, pushsync: move digest out of critical section; async handle of receipts --- pss/pss.go | 6 ++++-- pushsync/pusher.go | 2 +- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/pss/pss.go b/pss/pss.go index 98f13a6608..5e9b64a09e 100644 --- a/pss/pss.go +++ b/pss/pss.go @@ -854,10 +854,11 @@ func (p *Pss) addFwdCache(msg *PssMsg) error { var entry cacheEntry var ok bool + digest := p.msgDigest(msg) + p.fwdCacheMu.Lock() defer p.fwdCacheMu.Unlock() - digest := p.msgDigest(msg) if entry, ok = p.fwdCache[digest]; !ok { entry = cacheEntry{} } @@ -868,10 +869,11 @@ func (p *Pss) addFwdCache(msg *PssMsg) error { // check if message is in the cache func (p *Pss) checkFwdCache(msg *PssMsg) bool { + digest := p.msgDigest(msg) + p.fwdCacheMu.Lock() defer p.fwdCacheMu.Unlock() - digest := p.msgDigest(msg) entry, ok := p.fwdCache[digest] if ok { if entry.expiresAt.After(time.Now()) { diff --git a/pushsync/pusher.go b/pushsync/pusher.go index 91a6aef832..830590e0e3 100644 --- a/pushsync/pusher.go +++ b/pushsync/pusher.go @@ -252,7 +252,7 @@ func (p *Pusher) handleReceiptMsg(msg []byte) error { return err } p.logger.Trace("Handler", "receipt", label(receipt.Addr)) - p.pushReceipt(receipt.Addr) + go p.pushReceipt(receipt.Addr) return nil }