Protocol async errors refactor #2062

pradovic · 2019-12-23T15:22:57Z

Refactor all async handlers that use p2p.Protocol.Run() to not log errors in handlers, and not to use peer.Drop directly.

todo:

Add special error to allow handlers to return error to be logged but not break the execution. Identified places are commented with todo: handle nil error
There are a few more "double async" parts in a few already async handlers that still use peer.Drop(). Investigate and remove if possible (will be done in separate PR)

I have link this PR to #2058 at the moment, but I will merge them separately on master later. I did this as they are chronologically related.

…ol calls.

…otocols

pradovic · 2019-12-26T13:53:10Z

@janos , @zelig , I have updated PR with the idea how to handle different kind of errors. I have removed the old errors in p2p.Protocol as I did not really see them used anywhere logically, just for error messages.
Basically the idea is that special errors inside the handlers and p2p.Protocol define how they can be handled logically (should they break the loop, etc...), while handling them and logging additional context in the specific protocols present the information to the user. This whey we can add more specific errors, and log differently several use-cases, for ex. graceful shutdown, fatal error, blacklisting, etc...
Let me know do you think that approach makes sense, and if you like, we can brainstorm a bit about the log messages format on a different levels of protocol.

janos

I like the approach with BreakError (even thou I have comments on its implementation).

My comments are mostly on two topics. One is the logging and returning errors at the same time, which should not be done, as the error may be logged twice. The second is related to error messages. They can be simplified or shortened, buy removing words error, erroring, err:, reason: as they are errors implicitly. Also errors should not start with a capital letter, or have a form of full sentences. I have left comments on that, but not on all occurrences, as they would be mostly repetitive.

janos · 2019-12-26T14:20:22Z

bzzeth/bzzeth.go

@@ -135,8 +143,7 @@ func (b *BzzEth) handleNewBlockHeaders(ctx context.Context, p *Peer, msg *NewBlo
 	}
 	yes, err := b.netStore.Store.HasMulti(ctx, addresses...)
 	if err != nil {
-		log.Error("Error checking hashesh in store", "Reason", err)
-		return nil
+		return fmt.Errorf("error checking hashesh in store. Reason: %w", err)


I do not think that error and Reason is needed in message, Maybe something like check hashes: %w?

janos · 2019-12-26T14:21:12Z

bzzeth/bzzeth.go

@@ -79,6 +79,7 @@ func (b *BzzEth) Run(p *p2p.Peer, rw p2p.MsgReadWriter) error {
 	// perform handshake and register if peer serves headers
 	handshake, err := bp.Handshake(context.TODO(), Handshake{ServeHeaders: true}, nil)
 	if err != nil {
+		log.Error("Shutting down bzzeth protocol.", "peer", bp, "reason", err)


Error should not be logged and passed, just one of those.

This (and the next comment) were the things I wanted to discuss. I see 3 scenarios:

Log some context and message here and return nil

Log some context here and return a new specific error that will be seen in events in tests

Add more context too the error here and return an error. I am not sure if this error will be logged anywhere.

Scenario 3. is the one that I think is the correct one. We now have BreakError which is to make the peer drop, and any other error will be at least logged. If the error is logged and returned, it is easy to make the mistake to log the error twice. If the error is just passed, it is up to the caller to decide what to do, and the function that returns the error does not have to worry about it.

I agree, from the architecture point of view. I am just worried about the BreakErrors, which won't be logged in this case, right? This is probably the place that has enough information about what will happen to the specific protocol (ex. bzzeth, stream, etc...).

If there is a BreakError, then it should be logged as error before the peer is dropped.

The peer is actually dropped when the parent run function returns. This is why I was logging it here, as the drop is actually happening when it's propagated with end of the run function, in this case when BzzEth.Run() returns. This is why I was logging it here. The error returned by BzzEth.Run() is only used for events and testDisconnect. So, I see these options if we don't won't to log and return err message here:

Use peer.Drop() on error in p2p.Protocol and log BreakErrors there before drop. No need to return specific errors in p2p.Protocol.Run() then at all maybe?

Log the specific info here, and return different error to be shown in events and drop

I think the main question is, weather we need to return specific errors with p2p.Protocol.Run() and weather we want to rely on finishing Run() functions to drop a peer or do we want to drop a peer with peer.Drop().

Cool, as we discussed, option 1. would be a better compromise.

Ok, I have switched back to option 1. I don't like the fact that we lose a bit of control over the async errors. It's hard to check what caused protocol to stop, except that there is a log message. Of course, we could add the functionality in p2p.protocol to remember the drop error, and expose the API to check it. But maybe we can think about all this more in the future, and leave this as is for now, as we tried both approaches and it should not be to hard to switch back and forth between them.

janos · 2019-12-26T14:21:17Z

bzzeth/bzzeth.go

-	return peer.Run(b.handleMsg(bp))
+	err = peer.Run(b.handleMsg(bp))
+	if err != nil {
+		log.Error("Shutting down bzzeth protocol.", "peer", bp, "reason", err)


Error should not be logged and passed, just one of those.

janos · 2019-12-26T14:21:40Z

bzzeth/bzzeth.go

@@ -90,10 +91,17 @@ func (b *BzzEth) Run(p *p2p.Peer, rw p2p.MsgReadWriter) error {
 	// This protocol is all about interaction between an Eth node and a Swarm Node.
 	// If another swarm node tries to connect then the protocol goes into idle
 	if isSwarmNodeFunc(bp) {
-		return peer.Run(b.handleMsgFromSwarmNode(bp))
+		err = peer.Run(b.handleMsgFromSwarmNode(bp))


This error is shadowed later.

janos · 2019-12-26T14:23:05Z

bzzeth/bzzeth.go

@@ -118,7 +126,7 @@ func (b *BzzEth) handleMsg(p *Peer) func(context.Context, interface{}) error {
 func (b *BzzEth) handleMsgFromSwarmNode(p *Peer) func(context.Context, interface{}) error {
 	return func(ctx context.Context, msg interface{}) error {
 		p.logger.Warn("bzzeth.handleMsgFromSwarmNode")
-		return errRcvdMsgFromSwarmNode
+		return protocols.BreakError(errRcvdMsgFromSwarmNode)


Warning should be removed, even more as it does not add any context to the error.

janos · 2019-12-26T14:34:57Z

p2p/protocols/protocol.go

@@ -494,7 +437,7 @@ func (p *Peer) Handshake(ctx context.Context, hs interface{}, verify func(interf
 			err = ctx.Err()
 		}
 		if err != nil {
-			return nil, errorf(ErrHandshake, err.Error())
+			return nil, fmt.Errorf("%w", err)


No need to wrap error if there is no additional context.

janos · 2019-12-26T14:37:47Z

p2p/protocols/protocol_test.go

 		rw.eof = true
 		done := make(chan error)
 		go func() {
 			done <- eg.Wait()
 		}()
 		select {
 		case err := <-done:
-			if err != io.EOF {
-				t.Fatal("run returned error")
+			fmt.Println("in done")


Remove fmt.Println.

Debug line 🙈

janos · 2019-12-26T14:38:21Z

pss/pss.go

-	return pp.Run(handle)
+
+	if err := pp.Run(handle); err != nil {
+		log.Error("Shutting down pss protocol.", "peer", pp, "reason", err)


Error logged and returned.

janos · 2019-12-26T14:38:41Z

pss/pss.go

+		return fmt.Errorf("invalid message type: %s", msg)
+	}
+	if err := p.handlePssMsg(ctx, pssmsg); err != nil {
+		return fmt.Errorf("handler error: %w", err)


No need for word error in error message.

janos · 2019-12-26T14:40:56Z

network/stream/stream.go

-	return sp.Peer.Run(r.HandleMsg(sp))
+	// todo: log peer info appropriately
+	if err := sp.Peer.Run(r.HandleMsg(sp)); err != nil {
+		log.Error("Shutting down stream protocol.", "peer:", sp, "reason", err)


If there is an error, both log.Error and log.Info bellow will be printed.

acud

Wonderful work on this PR @pradovic! 👏 🍾
I have just a few minor comments

acud · 2020-01-08T05:14:59Z

bzzeth/bzzeth.go

@@ -418,11 +417,11 @@ DELIVERY:
 	if err == nil && deliveredCnt < total {
 		err := p.Send(ctx, &BlockHeaders{Rid: uint32(msg.Rid)})
 		if err != nil {
-			p.logger.Error("could not send empty BlockHeader", "err", err)
+			return fmt.Errorf("could not send empty BlockHeader: %w", err)


i am assuming that here peer is the ethereum node that expects the block headers. the send fails here, don't we want to break too?

acud · 2020-01-08T05:23:13Z

p2p/protocols/protocol.go

@@ -326,6 +252,10 @@ func (p *Peer) Drop(reason string) {
 // Returns nil if the active jobs are finished within the timeout duration, or error otherwise.
 func (p *Peer) Stop(timeout time.Duration) error {
 	p.mtx.Lock()
+	if p.running != true {


if !p.running

acud · 2020-01-08T05:23:54Z

p2p/protocols/protocol.go

@@ -359,7 +286,7 @@ func (p *Peer) Send(ctx context.Context, msg interface{}) error {

 	code, found := p.spec.GetCode(msg)
 	if !found {
-		return errorf(ErrInvalidMsgType, "%v", code)
+		return fmt.Errorf("invalid message type %v ", code)


probably better to break here. if the message code is not found - it means the nodes are incompatible and we should disconnect from that node

This is a sync call, as it is not using an event loop, so here we don't need to use a special error. This goes for Handshake() calls as well. Only run needs a special BreakError in order to break. Does this makes sense?

acud · 2020-01-08T05:24:36Z

p2p/protocols/protocol.go

@@ -459,7 +385,7 @@ func (p *Peer) handleMsg(msg p2p.Msg, handle func(ctx context.Context, msg inter
 // returns the remote handshake and an error
 func (p *Peer) Handshake(ctx context.Context, hs interface{}, verify func(interface{}) error) (interface{}, error) {
 	if _, ok := p.spec.GetCode(hs); !ok {
-		return nil, errorf(ErrHandshake, "unknown handshake message type: %T", hs)
+		return nil, fmt.Errorf("unknown handshake message type: %T", hs)


do we break as a result?

acud · 2020-01-08T05:26:41Z

pss/pss.go

-	return nil
+	pssmsg, ok := msg.(*message.Message)
+	if !ok {
+		return fmt.Errorf("invalid message type %s", msg)


not sure if we should break or not. @nolash ?

janos

Thanks, LGTM.

pradovic added 30 commits December 4, 2019 22:54

p2p: handleIncoming is now async

2684963

p2p, network, bzzeth, swap: split sync handshake and async run protoc…

62f4631

…ol calls.

p2p, retreival: graceful shutdown

3b98ab2

p2p, retreival: graceful shutdown

b10f406

p2p/protocol: fixed comments

5185cdb

p2p, network, swap: fixed test errors

2b1b975

p2p, network: cosmetic error change

c00c63a

p2p, network: return good err from async commands

a0aa962

p2p, network: graceful shutdown and bug/race fixes

44e92f6

p2p: remove debug logs

7835bca

bzzeth, network: fix bug and remove debug logs

45df85d

p2p, network: remove more bug logs

1f3726f

p2p, network: graceful shutdown in protocol run

c72b07c

bzzeth, network: errors.new to fmt.errof

266ada6

network: fix return error bug

a754cbe

network: fix return error bug

666c0a8

p2p: minor refactoring

f415525

p2p: unit tests for protocol.Receive

38ce6b8

p2p: unit tests for protocol.Run

5e8028c

p2p: unit tests for protocol.Run minor fix

3f14018

p2p, bzzeth, network: prune error messages and comments

a6ee45f

p2p: refactor async calls in protocol run

17f62db

p2p: use single global channel in protocol run

797925c

p2p: protocol shutdown fix

33d9391

p2p: protocol run loop fix

56d1600

p2p: remove unnecessary todo comment

f8cde08

p2p: renamed protocol shutdown to stop

6cecc23

p2p: removed global protocol chan

056974b

p2p, network: pr pruning

7bc1585

p2p: fix protocol tests

595b5b4

pradovic added 4 commits December 25, 2019 17:57

bzzeth: use async breakError

544dfaa

bzzeth, network, swap: use async breakError logic

994108c

bzzeth, network, p2p, pss, swap: log protocol shutdown in specific pr…

858175e

…otocols

p2p: removed unnecessary comments

0148660

pradovic requested a review from janos December 26, 2019 13:53

pradovic added 2 commits December 26, 2019 14:55

network: minor todo comment

012a017

network: fix stream protocol run

8a14644

janos reviewed Dec 26, 2019

View reviewed changes

pradovic added 5 commits December 26, 2019 15:50

swap: handle nil errors

41b9f11

bzzeth, network, p2p, pss, swap: switch to peer.Drop and fix tests

25c5003

bzzeth, network, p2p, pss, swap: prune error messages

9f11476

network, p2p, swap: fix couple of err messages

4fd097d

swap: prune some error messages

46c777a

pradovic added ready for review and removed in progress labels Dec 27, 2019

pradovic requested a review from janos December 27, 2019 16:29

pradovic requested a review from acud January 6, 2020 09:29

acud approved these changes Jan 8, 2020

View reviewed changes

p2p: minor style change in tests

2774f76

pradovic changed the base branch from protocol-msg-pauser to master January 9, 2020 11:31

pradovic added 5 commits January 10, 2020 15:54

merge master

f9955dd

p2p: go fmt

eedf43a

p2p: please the lint checks

1038ac7

bzzeth: fix a bug cuased by master merge

ff4607a

swap: merge master

7148206

janos approved these changes Jan 11, 2020

View reviewed changes

pradovic merged commit 07d6bd5 into master Jan 11, 2020

pradovic deleted the protocol-async-errors-refactor branch January 11, 2020 13:14

acud added this to the 0.5.5 milestone Jan 21, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Protocol async errors refactor #2062

Protocol async errors refactor #2062

pradovic commented Dec 23, 2019 •

edited

Loading

pradovic commented Dec 26, 2019 •

edited

Loading

janos left a comment

janos Dec 26, 2019

janos Dec 26, 2019

pradovic Dec 26, 2019

janos Dec 26, 2019

pradovic Dec 26, 2019

janos Dec 26, 2019

pradovic Dec 26, 2019 •

edited

Loading

janos Dec 26, 2019

pradovic Dec 26, 2019 •

edited

Loading

janos Dec 26, 2019

janos Dec 26, 2019

janos Dec 26, 2019

janos Dec 26, 2019

janos Dec 26, 2019

pradovic Dec 26, 2019

janos Dec 26, 2019 •

edited

Loading

janos Dec 26, 2019

janos Dec 26, 2019

acud left a comment

acud Jan 8, 2020

acud Jan 8, 2020

acud Jan 8, 2020

pradovic Jan 8, 2020 •

edited

Loading

acud Jan 8, 2020

acud Jan 8, 2020

janos left a comment

Protocol async errors refactor #2062

Protocol async errors refactor #2062

Conversation

pradovic commented Dec 23, 2019 • edited Loading

pradovic commented Dec 26, 2019 • edited Loading

janos left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pradovic Dec 26, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pradovic Dec 26, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

janos Dec 26, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

acud left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pradovic Jan 8, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

janos left a comment

Choose a reason for hiding this comment

pradovic commented Dec 23, 2019 •

edited

Loading

pradovic commented Dec 26, 2019 •

edited

Loading

pradovic Dec 26, 2019 •

edited

Loading

pradovic Dec 26, 2019 •

edited

Loading

janos Dec 26, 2019 •

edited

Loading

pradovic Jan 8, 2020 •

edited

Loading