Skip to content

Commit

Permalink
better logging (#26)
Browse files Browse the repository at this point in the history 
* better logging

* rename
  • Loading branch information
@nikkolasg
nikkolasg authored Jan 10, 2022
1 parent c5ce736 commit be0590a
Show file tree
Hide file tree
Showing 2 changed files with 56 additions and 43 deletions.
63 changes: 37 additions & 26 deletions share/dkg/dkg.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -403,21 +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")
d.c.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))
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
}

Expand All @@ -427,15 +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")
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)
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")
d.c.Error("Deal bundle already seen")
continue
}
seenIndex[bundle.DealerIndex] = true
Expand All @@ -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) {
Expand All @@ -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
}
Expand Down Expand Up @@ -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
Expand All @@ -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
}

Expand Down Expand Up @@ -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
}
Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -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)
}
}
Expand All @@ -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()
Expand All @@ -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))
}
}

Expand All @@ -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)
Expand All @@ -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
}

Expand Down Expand Up @@ -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...))
}
}

Expand Down
36 changes: 19 additions & 17 deletions share/dkg/protocol.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand All @@ -247,15 +249,15 @@ 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
// 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()))
p.Info("fast moving to finish phase phase", fmt.Sprintf("got %d resps", justifs.Len()))
return
}
}
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
}
Expand Down

0 comments on commit be0590a

Please sign in to comment.