From be0590a2402c54999876ce179294f720443e4bd2 Mon Sep 17 00:00:00 2001 From: Nicolas Gailly Date: Mon, 10 Jan 2022 19:21:01 +0100 Subject: [PATCH] better logging (#26) * better logging * rename --- share/dkg/dkg.go | 63 +++++++++++++++++++++++++------------------ share/dkg/protocol.go | 36 +++++++++++++------------ 2 files changed, 56 insertions(+), 43 deletions(-) diff --git a/share/dkg/dkg.go b/share/dkg/dkg.go index 9027e62af..3ddf967c7 100644 --- a/share/dkg/dkg.go +++ b/share/dkg/dkg.go @@ -114,7 +114,7 @@ type Config struct { // errors). from participants. Errors don't mean the protocol should be // stopped, so logging is the best way to communicate information to the // application layer. It can be nil. - Logger func(keyvals ...interface{}) + Log Logger } // Phase is a type that represents the different stages of the DKG protocol. @@ -403,7 +403,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, seenIndex := make(map[uint32]bool) for _, bundle := range bundles { if bundle == nil { - d.Log("error", "found nil Deal bundle") + d.c.Error("found nil Deal bundle") continue } if d.canIssue && bundle.DealerIndex == uint32(d.oidx) { @@ -411,13 +411,13 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, continue } if !isIndexIncluded(d.c.OldNodes, bundle.DealerIndex) { - d.Log("error", fmt.Sprintf("dealer %d not in OldNodes", bundle.DealerIndex)) + d.c.Error(fmt.Sprintf("dealer %d not in OldNodes", bundle.DealerIndex)) continue } if bytes.Compare(bundle.SessionID, d.c.Nonce) != 0 { d.evicted = append(d.evicted, bundle.DealerIndex) - d.Log("error", "Deal with invalid session ID") + d.c.Error("Deal with invalid session ID") continue } @@ -427,7 +427,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, // since we assume broadcast channel, every honest player will evict // this party as well d.evicted = append(d.evicted, bundle.DealerIndex) - d.Log("error", "Deal with nil public key or invalid threshold") + d.c.Error("Deal with nil public key or invalid threshold") continue } pubPoly := share.NewPubPoly(d.c.Suite, d.c.Suite.Point().Base(), bundle.Public) @@ -435,7 +435,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, // already saw a bundle from the same dealer - clear sign of // cheating so we evict him from the list d.evicted = append(d.evicted, bundle.DealerIndex) - d.Log("error", "Deal bundle already seen") + d.c.Error("Deal bundle already seen") continue } seenIndex[bundle.DealerIndex] = true @@ -446,7 +446,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, // so we evict him from the list // and we don't even need to look at the rest d.evicted = append(d.evicted, bundle.DealerIndex) - d.Log("error", "Deal share holder evicted normally") + d.c.Error("Deal share holder evicted normally") break } if deal.ShareIndex != uint32(d.nidx) { @@ -455,19 +455,19 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, } shareBuff, err := ecies.Decrypt(d.c.Suite, d.long, deal.EncryptedShare, sha256.New) if err != nil { - d.Log("error", "Deal share decryption invalid") + d.c.Error("Deal share decryption invalid") continue } share := d.c.Suite.Scalar() if err := share.UnmarshalBinary(shareBuff); err != nil { - d.Log("error", "Deal share unmarshalling invalid") + d.c.Error("Deal share unmarshalling invalid") continue } // check if share is valid w.r.t. public commitment comm := pubPoly.Eval(int(d.nidx)).V commShare := d.c.Suite.Point().Mul(share, nil) if !comm.Equal(commShare) { - d.Log("error", "Deal share invalid wrt public poly") + d.c.Error("Deal share invalid wrt public poly") // invalid share - will issue complaint continue } @@ -524,7 +524,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, DealerIndex: uint32(node.Index), Status: Complaint, }) - d.Log("info", fmt.Sprintf("Complaint towards node %d", node.Index)) + d.c.Info(fmt.Sprintf("Complaint towards node %d", node.Index)) } } var bundle *ResponseBundle @@ -541,7 +541,7 @@ func (d *DistKeyGenerator) ProcessDeals(bundles []*DealBundle) (*ResponseBundle, bundle.Signature = sig } d.state = ResponsePhase - d.Log("info", fmt.Sprintf("sending back %d responses", len(responses))) + d.c.Info(fmt.Sprintf("sending back %d responses", len(responses))) return bundle, nil } @@ -581,12 +581,12 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, continue } if !isIndexIncluded(d.c.NewNodes, bundle.ShareIndex) { - d.Log("error", "Response author already evicted") + d.c.Error("Response author already evicted") continue } if bytes.Compare(bundle.SessionID, d.c.Nonce) != 0 { - d.Log("error", "Response invalid session ID") + d.c.Error("Response invalid session ID") d.evictedHolders = append(d.evictedHolders, bundle.ShareIndex) continue } @@ -596,7 +596,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, // the index of the dealer doesn't exist - clear violation // so we evict d.evictedHolders = append(d.evictedHolders, bundle.ShareIndex) - d.Log("error", "Response dealer index already evicted") + d.c.Error("Response dealer index already evicted") continue } @@ -605,7 +605,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, // mode - clear violation // so we evict d.evictedHolders = append(d.evictedHolders, bundle.ShareIndex) - d.Log("error", "Response success but in regular mode") + d.c.Error("Response success but in regular mode") continue } @@ -631,7 +631,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, continue // we dont evict ourself } if !contains(allSent, n.Index) { - d.Log("error", fmt.Sprintf("Response not seen from node %d (eviction)", n.Index)) + d.c.Error(fmt.Sprintf("Response not seen from node %d (eviction)", n.Index)) d.evictedHolders = append(d.evictedHolders, n.Index) } } @@ -641,7 +641,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, // is all filled with success that means we can finish the protocol - // regardless of the mode chosen (fast sync or not). if !foundComplaint && d.statuses.CompleteSuccess() { - d.Log("info", "DKG successful") + d.c.Info("DKG successful") d.state = FinishPhase if d.canReceive { res, err := d.computeResult() @@ -659,7 +659,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, complaints := d.statuses.StatusesOfDealer(n.Index).LengthComplaints() if complaints >= d.c.Threshold { d.evicted = append(d.evicted, n.Index) - d.Log("error", fmt.Sprintf("Response phase eviction of node %d", n.Index)) + d.c.Error(fmt.Sprintf("Response phase eviction of node %d", n.Index)) } } @@ -684,7 +684,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, ShareIndex: shareIndex, Share: sh, }) - d.Log("dkg-event", fmt.Sprintf("Producing justifications for node %d", shareIndex)) + d.c.Info(fmt.Sprintf("Producing justifications for node %d", shareIndex)) foundJustifs = true // mark those shares as resolved in the statuses d.statuses.Set(uint32(d.oidx), shareIndex, true) @@ -702,7 +702,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, signature, err := d.sign(bundle) bundle.Signature = signature - d.Log("dkg-event", "Justifications returned") + d.c.Info(fmt.Sprintf("%d justifications returned", len(justifications))) return nil, bundle, err } @@ -1071,12 +1071,23 @@ func (d *DistKeyGenerator) sign(p Packet) ([]byte, error) { return d.c.Auth.Sign(priv, msg) } +func (d *DistKeyGenerator) Info(keyvals ...interface{}) { + d.c.Info(append([]interface{}{"generator"}, keyvals...)) +} + +func (d *DistKeyGenerator) Error(keyvals ...interface{}) { + d.c.Info(append([]interface{}{"generator"}, keyvals...)) +} + +func (c *Config) Info(keyvals ...interface{}) { + if c.Log != nil { + c.Log.Info(append([]interface{}{"dkg-log"}, keyvals...)) + } +} -// Log tries to log the given entries only if the logger has been set in the -// config -func (d *DistKeyGenerator) Log(keyvals ...interface{}) { - if d.c.Logger != nil { - d.c.Logger(append([]interface{}{"dkg-log"}, keyvals...)) +func (c *Config) Error(keyvals ...interface{}) { + if c.Log != nil { + c.Log.Error(append([]interface{}{"dkg-log"}, keyvals...)) } } diff --git a/share/dkg/protocol.go b/share/dkg/protocol.go index cb07e4359..9599d5302 100644 --- a/share/dkg/protocol.go +++ b/share/dkg/protocol.go @@ -105,10 +105,12 @@ func NewProtocol(c *Config, b Board, phaser Phaser, skipVerification bool) (*Pro return p, nil } -func (p *Protocol) Log(keyvals ...interface{}) { - if p.dkg.c.Logger != nil { - p.dkg.c.Logger(append([]interface{}{"source", "dkg-proto"}, keyvals...)) - } +func (p *Protocol) Info(keyvals ...interface{}) { + p.dkg.c.Info(append([]interface{}{"protocol"}, keyvals...)) +} + +func (p *Protocol) Error(keyvals ...interface{}) { + p.dkg.c.Error(append([]interface{}{"protocol"}, keyvals...)) } func (p *Protocol) Start() { @@ -200,17 +202,17 @@ func (p *Protocol) startFast() { case newPhase := <-p.phaser.NextPhase(): switch newPhase { case DealPhase: - p.Log("phaser", "moving to sending deals phase") + p.Info("phaser", "moving to sending deals phase") if !p.sendDeals() { return } case ResponsePhase: - p.Log("phaser", fmt.Sprintf("moving to response phase, got %d deals", deals.Len())) + p.Info("phaser", fmt.Sprintf("moving to response phase, got %d deals", deals.Len())) if !toResp() { return } case JustifPhase: - p.Log("phaser", fmt.Sprintf("moving to justifications phase, got %d resps", resps.Len())) + p.Info("phaser", fmt.Sprintf("moving to justifications phase, got %d resps", resps.Len())) if !toJust() { return } @@ -223,10 +225,10 @@ func (p *Protocol) startFast() { if err := p.verify(&newDeal); err == nil { deals.Push(&newDeal) } else { - p.Log("error", "Received invalid deal signature") + p.Error("invalid deal signature:", err) } if deals.Len() == oldN { - p.Log("info", fmt.Sprintf("fast moving to response phase, got %d deals", oldN)) + p.Info("fast moving to response phase", fmt.Sprintf(" got %d deals", oldN)) if !toResp() { return } @@ -235,10 +237,10 @@ func (p *Protocol) startFast() { if err := p.verify(&newResp); err == nil { resps.Push(&newResp) } else { - p.Log("error", "Received invalid response signature") + p.Error("Received invalid response signature:", err) } if resps.Len() == newN { - p.Log("info", fmt.Sprintf("fast moving to justifications phase, got %d resps", newN)) + p.Info("fast moving to justifications phase", fmt.Sprintf("got %d resps", newN)) if !toJust() { return } @@ -247,7 +249,7 @@ func (p *Protocol) startFast() { if err := p.verify(&newJust); err == nil { justifs.Push(&newJust) } else { - p.Log("error", "Received invalid justification signature") + p.Error("invalid justification signature:", err) } if justifs.Len() == oldN { // we finish only if it's time to do so, maybe we received @@ -255,7 +257,7 @@ func (p *Protocol) startFast() { // may not be the right time or haven't received enough msg from // previous phase if !toFinish() { - p.Log("info", fmt.Sprintf("fast moving to finish phase phase, got %d resps", justifs.Len())) + p.Info("fast moving to finish phase phase", fmt.Sprintf("got %d resps", justifs.Len())) return } } @@ -283,7 +285,7 @@ func (p *Protocol) sendDeals() bool { return false } if bundle != nil { - p.Log("info", fmt.Sprintf("Sending out the bundle with %d deals", len(bundle.Deals))) + p.Info("Sending out deal bundle", fmt.Sprintf("%d deals", len(bundle.Deals))) p.board.PushDeals(bundle) } return true @@ -299,7 +301,7 @@ func (p *Protocol) sendResponses(deals []*DealBundle) bool { return false } if bundle != nil { - p.Log("info", fmt.Sprintf("Sending out responses (from %d deals)", len(deals))) + p.Info("sending out response bundle", fmt.Sprintf("from %d deals", len(deals))) p.board.PushResponses(bundle) } return true @@ -315,10 +317,10 @@ func (p *Protocol) sendJustifications(resps []*ResponseBundle) bool { return false } if just != nil { - p.Log("info", fmt.Sprintf("node sends justifications out (from %d responses)", len(resps))) + p.Info("sending justification", fmt.Sprintf("from %d responses", len(resps))) p.board.PushJustifications(just) } else { - p.Log("info", "DKG finished in response phase") + p.Info("DKG FINISH", "from response phase") } return true }