Some log fixes (#920)

* Fixing logs
* Updating to use Kyber with fixed logging in DKG

chain/beacon/node.go

@@ -118,33 +118,35 @@ func (h *Handler) ProcessPartialBeacon(c context.Context, p *proto.PartialBeacon
 
 	msg := h.verifier.DigestMessage(p.GetRound(), p.GetPreviousSig())
 
-	// XXX Remove that evaluation - find another way to show the current dist.
-	// key being used
-	shortPub := h.crypto.GetPub().Eval(1).V.String()[14:19]
+	idx, _ := key.Scheme.IndexOf(p.GetPartialSig())
+	if idx < 0 {
+		return nil, fmt.Errorf("invalid index %d in partial with msg %v", idx, msg)
+	}
+	nodeName := h.crypto.GetGroup().Node(uint32(idx)).Identity.Address()
 	// verify if request is valid
 	if err := key.Scheme.VerifyPartial(h.crypto.GetPub(), msg, p.GetPartialSig()); err != nil {
 		h.l.Errorw("", "beacon_id", beaconID,
 			"process_partial", addr, "err", err,
 			"prev_sig", shortSigStr(p.GetPreviousSig()),
 			"curr_round", currentRound,
 			"msg_sign", shortSigStr(msg),
-			"short_pub", shortPub)
+			"from_node", nodeName)
 		return nil, err
 	}
 	h.l.Debugw("", "beacon_id", beaconID,
 		"process_partial", addr,
 		"prev_sig", shortSigStr(p.GetPreviousSig()),
-		"curr_round", currentRound, "msg_sign",
-		shortSigStr(msg), "short_pub", shortPub,
+		"curr_round", currentRound,
+		"msg_sign", shortSigStr(msg),
+		"from_node", nodeName,
 		"status", "OK")
-	idx, _ := key.Scheme.IndexOf(p.GetPartialSig())
 	if idx == h.crypto.Index() {
 		h.l.Errorw("", "beacon_id", beaconID,
 			"process_partial", addr,
 			"index_got", idx,
 			"index_our", h.crypto.Index(),
 			"advance_packet", p.GetRound(),
-			"pub", shortPub)
+			"from_node", nodeName)
 		// XXX error or not ?
 		return new(proto.Empty), nil
 	}

core/broadcast.go

@@ -89,7 +89,7 @@ func (b *echoBroadcast) PushDeals(bundle *dkg.DealBundle) {
 	b.Lock()
 	defer b.Unlock()
 	h := hash(bundle.Hash())
-	b.l.Debugw("", "beacon_id", b.beaconID, "echoBroadcast", "push", "deal")
+	b.l.Debugw("", "beacon_id", b.beaconID, "echoBroadcast", "push", "deal", fmt.Sprintf("%x", h[:5]))
 	b.sendout(h, bundle, true)
 }
 
@@ -107,7 +107,7 @@ func (b *echoBroadcast) PushJustifications(bundle *dkg.JustificationBundle) {
 	b.Lock()
 	defer b.Unlock()
 	h := hash(bundle.Hash())
-	b.l.Debugw("", "beacon_id", b.beaconID, "echoBroadcast", "push", "justification")
+	b.l.Debugw("", "beacon_id", b.beaconID, "echoBroadcast", "push", "justification", fmt.Sprintf("%x", h[:5]))
 	b.sendout(h, bundle, true)
 }
 

core/drand_beacon_control.go

@@ -272,7 +272,7 @@ func (bp *BeaconProcess) leaderRunSetup(newSetup func(d *BeaconProcess) (*setupM
 	bp.state.Lock()
 
 	if bp.manager != nil {
-		bp.log.Infow("", "beacon_id", bp.manager.beaconID, "reshare", "already_in_progress", "restart", "reshare", "old")
+		bp.log.Infow("", "beacon_id", bp.manager.beaconID, "reshare", "already_in_progress", "reshare", "restart")
 		fmt.Println("\n\n PRE EMPTIVE STOP")
 		bp.manager.StopPreemptively()
 	}
@@ -1103,7 +1103,7 @@ func (bp *BeaconProcess) StartFollowChain(req *drand.StartFollowRequest, stream
 	defer cbStore.RemoveCallback(addr)
 
 	if err := syncer.Follow(ctx, req.GetUpTo(), peers); err != nil {
-		bp.log.Errorw("", "beacon_id", beaconID, "start_follow_chain", "syncer_stopped", "err", err, "leaving_sync")
+		bp.log.Errorw("", "beacon_id", beaconID, "start_follow_chain", "syncer_stopped", "err", err, "state", "leaving_sync")
 		return err
 	}
 

go.mod

@@ -6,7 +6,7 @@ require (
 	github.com/BurntSushi/toml v0.3.1
 	github.com/aws/aws-sdk-go v1.32.11
 	github.com/briandowns/spinner v1.11.1
-	github.com/drand/kyber v1.1.9
+	github.com/drand/kyber v1.1.10
 	github.com/drand/kyber-bls12381 v0.2.1
 	github.com/go-chi/chi v1.5.4
 	github.com/google/uuid v1.3.0

go.sum

@@ -113,8 +113,8 @@ github.com/drand/bls12-381 v0.3.2/go.mod h1:dtcLgPtYT38L3NO6mPDYH0nbpc5tjPassDqi
 github.com/drand/kyber v1.0.1-0.20200110225416-8de27ed8c0e2/go.mod h1:UpXoA0Upd1N9l4TvRPHr1qAUBBERj6JQ/mnKI3BPEmw=
 github.com/drand/kyber v1.0.2/go.mod h1:x6KOpK7avKj0GJ4emhXFP5n7M7W7ChAPmnQh/OL6vRw=
 github.com/drand/kyber v1.1.4/go.mod h1:9+IgTq7kadePhZg7eRwSD7+bA+bmvqRK+8DtmoV5a3U=
-github.com/drand/kyber v1.1.9 h1:XlKRGLH75of0ehRrX8HSdfcsa1Ld5p5/615Hvq/YCWA=
-github.com/drand/kyber v1.1.9/go.mod h1:UkHLsI4W6+jT5PvNxmc0cvQAgppjTUpX+XCsN9TXmRo=
+github.com/drand/kyber v1.1.10 h1:nQz5hahL68HDvdtwshZpe/qo3enM8gaL/Ou4Bnkw6iE=
+github.com/drand/kyber v1.1.10/go.mod h1:UkHLsI4W6+jT5PvNxmc0cvQAgppjTUpX+XCsN9TXmRo=
 github.com/drand/kyber-bls12381 v0.2.0/go.mod h1:zQip/bHdeEB6HFZSU3v+d3cQE0GaBVQw9aR2E7AdoeI=
 github.com/drand/kyber-bls12381 v0.2.1 h1:/d5/YAdaCmHpYjF1NZevOEcKGaq6LBbyvkCTIdGqDjs=
 github.com/drand/kyber-bls12381 v0.2.1/go.mod h1:JwWn4nHO9Mp4F5qCie5sVIPQZ0X6cw8XAeMRvc/GXBE=

log/log_test.go

@@ -77,6 +77,23 @@ func TestLoggerKit(t *testing.T) {
 	}
 }
 
+func TestOddKV(t *testing.T) {
+	var b bytes.Buffer
+	writer := bufio.NewWriter(&b)
+	syncer := zapcore.AddSync(writer)
+
+	logger := NewLogger(syncer, LogInfo)
+	logger = logger.With([]interface{}{"yard", "bird", "stone"}...)
+
+	logger.Info("msg=", "hello")
+	writer.Flush()
+
+	out := b.String()
+
+	require.Contains(t, out, "msg=hello")
+	require.Contains(t, out, "Ignored key without a value.")
+}
+
 func requireContains(t *testing.T, r io.Reader, outs []string, present bool) {
 	out, err := io.ReadAll(r)
 	require.NoError(t, err)
@@ -87,4 +104,5 @@ func requireContains(t *testing.T, r io.Reader, outs []string, present bool) {
 	for _, o := range outs {
 		require.Contains(t, string(out), o)
 	}
+	require.NotContains(t, string(out), "Ignored key without a value.")
 }