From c5ce7365c1b38a25acaf66af8735d1e95f7a9a23 Mon Sep 17 00:00:00 2001 From: Nicolas Gailly Date: Mon, 10 Jan 2022 16:37:06 +0100 Subject: [PATCH] Basic Logging capability for DKG (#24) * logging infra * removed compilation error * adding log when sending deals * key value logs --- share/dkg/dkg.go | 35 +++++++++++++++++++++++++++++++++++ share/dkg/logger.go | 7 +++++++ share/dkg/protocol.go | 23 +++++++++++++++++++++++ 3 files changed, 65 insertions(+) create mode 100644 share/dkg/logger.go diff --git a/share/dkg/dkg.go b/share/dkg/dkg.go index a5c99fcf8..9027e62af 100644 --- a/share/dkg/dkg.go +++ b/share/dkg/dkg.go @@ -109,6 +109,12 @@ type Config struct { // Auth is the scheme to use to authentify the packets sent and received // during the protocol. Auth sign.Scheme + + // Log enables the DKG logic and protocol to log important events (mostly + // 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{}) } // Phase is a type that represents the different stages of the DKG protocol. @@ -397,6 +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") continue } if d.canIssue && bundle.DealerIndex == uint32(d.oidx) { @@ -404,11 +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)) 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") continue } @@ -418,6 +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") continue } pubPoly := share.NewPubPoly(d.c.Suite, d.c.Suite.Point().Base(), bundle.Public) @@ -425,6 +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") continue } seenIndex[bundle.DealerIndex] = true @@ -435,6 +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") break } if deal.ShareIndex != uint32(d.nidx) { @@ -443,16 +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") continue } share := d.c.Suite.Scalar() if err := share.UnmarshalBinary(shareBuff); err != nil { + d.Log("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") // invalid share - will issue complaint continue } @@ -509,6 +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)) } } var bundle *ResponseBundle @@ -525,6 +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))) return bundle, nil } @@ -564,10 +581,12 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, continue } if !isIndexIncluded(d.c.NewNodes, bundle.ShareIndex) { + d.Log("error", "Response author already evicted") continue } if bytes.Compare(bundle.SessionID, d.c.Nonce) != 0 { + d.Log("error", "Response invalid session ID") d.evictedHolders = append(d.evictedHolders, bundle.ShareIndex) continue } @@ -577,6 +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") continue } @@ -585,6 +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") continue } @@ -610,6 +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.evictedHolders = append(d.evictedHolders, n.Index) } } @@ -619,6 +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.state = FinishPhase if d.canReceive { res, err := d.computeResult() @@ -636,6 +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)) } } @@ -660,6 +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)) foundJustifs = true // mark those shares as resolved in the statuses d.statuses.Set(uint32(d.oidx), shareIndex, true) @@ -677,6 +702,7 @@ func (d *DistKeyGenerator) ProcessResponses(bundles []*ResponseBundle) (*Result, signature, err := d.sign(bundle) bundle.Signature = signature + d.Log("dkg-event", "Justifications returned") return nil, bundle, err } @@ -1045,6 +1071,15 @@ func (d *DistKeyGenerator) sign(p Packet) ([]byte, error) { return d.c.Auth.Sign(priv, msg) } + +// 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...)) + } +} + // CheckForDuplicates looks at the lits of node indices in the OldNodes and // NewNodes list. It returns an error if there is a duplicate in either list. // NOTE: It only looks at indices because it is plausible that one party may diff --git a/share/dkg/logger.go b/share/dkg/logger.go new file mode 100644 index 000000000..f301ff329 --- /dev/null +++ b/share/dkg/logger.go @@ -0,0 +1,7 @@ +package dkg + +// Logger is a simpler key value logger interface +type Logger interface { + Info(keyvals ...interface{}) + Error(keyvals ...interface{}) +} diff --git a/share/dkg/protocol.go b/share/dkg/protocol.go index 8a5f52dda..cb07e4359 100644 --- a/share/dkg/protocol.go +++ b/share/dkg/protocol.go @@ -105,6 +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) Start() { var fastSync = p.dkg.c.FastSync if fastSync { @@ -194,14 +200,17 @@ func (p *Protocol) startFast() { case newPhase := <-p.phaser.NextPhase(): switch newPhase { case DealPhase: + p.Log("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())) if !toResp() { return } case JustifPhase: + p.Log("phaser", fmt.Sprintf("moving to justifications phase, got %d resps", resps.Len())) if !toJust() { return } @@ -213,8 +222,11 @@ func (p *Protocol) startFast() { case newDeal := <-p.board.IncomingDeal(): if err := p.verify(&newDeal); err == nil { deals.Push(&newDeal) + } else { + p.Log("error", "Received invalid deal signature") } if deals.Len() == oldN { + p.Log("info", fmt.Sprintf("fast moving to response phase, got %d deals", oldN)) if !toResp() { return } @@ -222,8 +234,11 @@ func (p *Protocol) startFast() { case newResp := <-p.board.IncomingResponse(): if err := p.verify(&newResp); err == nil { resps.Push(&newResp) + } else { + p.Log("error", "Received invalid response signature") } if resps.Len() == newN { + p.Log("info", fmt.Sprintf("fast moving to justifications phase, got %d resps", newN)) if !toJust() { return } @@ -231,6 +246,8 @@ func (p *Protocol) startFast() { case newJust := <-p.board.IncomingJustification(): if err := p.verify(&newJust); err == nil { justifs.Push(&newJust) + } else { + p.Log("error", "Received invalid justification signature") } if justifs.Len() == oldN { // we finish only if it's time to do so, maybe we received @@ -238,6 +255,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())) return } } @@ -265,6 +283,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.board.PushDeals(bundle) } return true @@ -280,6 +299,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.board.PushResponses(bundle) } return true @@ -295,7 +315,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.board.PushJustifications(just) + } else { + p.Log("info", "DKG finished in response phase") } return true }