Basic Logging capability for DKG (#24)

* logging infra

* removed compilation error

* adding log when sending deals

* key value logs

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,18 +403,21 @@ 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) {
 			// dont look at our own deal
 			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,13 +427,15 @@ 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)
 		if seenIndex[bundle.DealerIndex] {
 			// 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

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{})
+}

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,31 +222,40 @@ 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
 				}
 			}
 		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
 				}
 			}
 		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
 				// justifications but are not in the right phase yet since it
 				// 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
 }