Merge pull request #407 from shutter-network/ezdac/shmtlogging

feat: improve logging in shuttermint

Author: ulope

rolling-shutter/keyper/fx/send.go

@@ -33,7 +33,8 @@ func SendShutterMessages(
 		if err != nil {
 			return err // XXX retry
 		}
-		log.Info().Int32("id", outgoing.ID).Str("description", outgoing.Description).
+		log.Info().Int32("id", outgoing.ID).
+			Str("description", outgoing.Description).
 			Msg("send shuttermint message")
 		err = queries.DeleteShutterMessage(ctx, outgoing.ID)
 		if err != nil {

rolling-shutter/keyper/keyper.go

@@ -3,6 +3,7 @@ package keyper
 
 import (
 	"context"
+	"fmt"
 	"time"
 
 	"github.com/ethereum/go-ethereum/ethclient"
@@ -172,7 +173,7 @@ func (kpr *keyper) handleOnChainChanges(
 	tx pgx.Tx,
 	l1BlockNumber uint64,
 ) error {
-	log.Info().Uint64("l1-block-number", l1BlockNumber).Msg("handle on chain changes")
+	log.Debug().Uint64("l1-block-number", l1BlockNumber).Msg("handle on chain changes")
 	err := kpr.handleOnChainKeyperSetChanges(ctx, tx, l1BlockNumber)
 	if err != nil {
 		return err
@@ -208,7 +209,11 @@ func (kpr *keyper) sendNewBlockSeen(ctx context.Context, tx pgx.Tx, l1BlockNumbe
 	}
 
 	blockSeenMsg := shmsg.NewBlockSeen(l1BlockNumber)
-	err = q.ScheduleShutterMessage(ctx, "block seen", blockSeenMsg)
+	err = q.ScheduleShutterMessage(
+		ctx,
+		fmt.Sprintf("block seen (block=%d)", l1BlockNumber),
+		blockSeenMsg,
+	)
 	if err != nil {
 		return err
 	}
@@ -289,7 +294,12 @@ func (kpr *keyper) handleOnChainKeyperSetChanges(
 		uint64(keyperSet.Threshold),
 		uint64(keyperSet.KeyperConfigIndex),
 	)
-	err = q.ScheduleShutterMessage(ctx, "new batch config", batchConfigMsg)
+	err = q.ScheduleShutterMessage(
+		ctx,
+		fmt.Sprintf("new batch config (activation-block-number=%d, config-index=%d)",
+			keyperSet.ActivationBlockNumber, keyperSet.KeyperConfigIndex),
+		batchConfigMsg,
+	)
 	if err != nil {
 		return err
 	}

rolling-shutter/keyper/shutterevents/events.go

@@ -30,8 +30,8 @@ type Accusation struct {
 
 func (acc *Accusation) String() string {
 	return fmt.Sprintf(
-		"Accusation{Height: %d, Eon: %d, Sender: %s, Accused: %s}",
-		acc.Height, acc.Eon, acc.Sender, acc.Accused)
+		"Accusation{Height=%d, Eon=%d, Sender=%s, Accused=%s}",
+		acc.Height, acc.Eon, acc.Sender.String(), encodeAddresses(acc.Accused))
 }
 
 func (acc Accusation) MakeABCIEvent() abcitypes.Event {
@@ -104,8 +104,8 @@ type Apology struct {
 
 func (msg *Apology) String() string {
 	return fmt.Sprintf(
-		"Apology{Height: %d, Eon: %d, Sender: %s, Accusers: %s}",
-		msg.Height, msg.Eon, msg.Sender, msg.Accusers)
+		"Apology{Height=%d, Eon=%d, Sender=%s, Accusers=%s}",
+		msg.Height, msg.Eon, msg.Sender, encodeAddresses(msg.Accusers))
 }
 
 func (msg Apology) MakeABCIEvent() abcitypes.Event {
@@ -178,6 +178,19 @@ type BatchConfig struct {
 	ValidatorsUpdated     bool
 }
 
+func (bc *BatchConfig) String() string {
+	return fmt.Sprintf(
+		"BatchConfig{Height=%d, Keypers=%s, ActivationBlockNumber=%d, Threshold=%d, ConfigIndex=%d, Started=%t, ValidatorsUpdated=%t}",
+		bc.Height,
+		encodeAddresses(bc.Keypers),
+		bc.ActivationBlockNumber,
+		bc.Threshold,
+		bc.KeyperConfigIndex,
+		bc.Started,
+		bc.ValidatorsUpdated,
+	)
+}
+
 func (bc BatchConfig) MakeABCIEvent() abcitypes.Event {
 	return abcitypes.Event{
 		Type: evtype.BatchConfig,
@@ -255,6 +268,14 @@ func (bcs BatchConfigStarted) MakeABCIEvent() abcitypes.Event {
 	}
 }
 
+func (bcs *BatchConfigStarted) String() string {
+	return fmt.Sprintf(
+		"BatchConfigStarted{Height=%d, ConfigIndex=%d}",
+		bcs.Height,
+		bcs.KeyperConfigIndex,
+	)
+}
+
 // makeBatchConfigStarted creates a BatchConfigEvent from the given tendermint event of type
 // "shutter.batch-config-started".
 func makeBatchConfigStarted(ev abcitypes.Event, height int64) (*BatchConfigStarted, error) {
@@ -292,6 +313,14 @@ func (msg CheckIn) MakeABCIEvent() abcitypes.Event {
 	}
 }
 
+func (msg *CheckIn) String() string {
+	return fmt.Sprintf(
+		"CheckIn{Height=%d, Sender=%s}",
+		msg.Height,
+		msg.Sender.String(),
+	)
+}
+
 // makeCheckIn creates a CheckInEvent from the given tendermint event of type "shutter.check-in".
 func makeCheckIn(ev abcitypes.Event, height int64) (*CheckIn, error) {
 	err := expectAttributes(ev, "Sender", "EncryptionPublicKey")
@@ -335,6 +364,16 @@ func (msg EonStarted) MakeABCIEvent() abcitypes.Event {
 	}
 }
 
+func (msg *EonStarted) String() string {
+	return fmt.Sprintf(
+		"EonStarted{Height=%d, Eon=%d, ActivationBlockNumber=%d, ConfigIndex=%d}",
+		msg.Height,
+		msg.Eon,
+		msg.ActivationBlockNumber,
+		msg.KeyperConfigIndex,
+	)
+}
+
 // PolyCommitment represents a broadcasted polynomial commitment message.
 type PolyCommitment struct {
 	Height int64
@@ -348,7 +387,7 @@ func (msg *PolyCommitment) String() string {
 		"PolyCommitment{Height=%d, Eon=%d, Sender=%s}",
 		msg.Height,
 		msg.Eon,
-		msg.Sender,
+		msg.Sender.String(),
 	)
 }
 
@@ -402,11 +441,11 @@ type PolyEval struct {
 
 func (msg *PolyEval) String() string {
 	return fmt.Sprintf(
-		"PolyEval{Height: %d, Sender: %s, Eon: %d, Receivers: %s}",
+		"PolyEval{Height=%d, Sender=%s, Eon=%d, Receivers=%s}",
 		msg.Height,
 		msg.Sender,
 		msg.Eon,
-		msg.Receivers)
+		encodeAddresses(msg.Receivers))
 }
 
 func (msg PolyEval) MakeABCIEvent() abcitypes.Event {
@@ -459,6 +498,7 @@ func makePolyEval(ev abcitypes.Event, height int64) (*PolyEval, error) {
 // IEvent is an interface for the event types declared above.
 type IEvent interface {
 	MakeABCIEvent() abcitypes.Event
+	String() string
 }
 
 // makeEonStarted creates a EonStartedEvent from the given tendermint event of type

rolling-shutter/keyper/smobserver/smstate.go

@@ -5,6 +5,7 @@ import (
 	"crypto/ed25519"
 	"crypto/rand"
 	"database/sql"
+	"encoding/hex"
 	"fmt"
 	"math"
 	"math/big"
@@ -199,7 +200,7 @@ func (st *ShuttermintState) sendPolyEvals(ctx context.Context, queries *kprdb.Qu
 		}()
 		return queries.ScheduleShutterMessage(
 			ctx,
-			fmt.Sprintf("poly eval eon=%d", currentEon),
+			fmt.Sprintf("poly eval (eon=%d)", currentEon),
 			shmsg.NewPolyEval(uint64(currentEon), receivers, encryptedEvals),
 		)
 	}
@@ -248,11 +249,12 @@ func (st *ShuttermintState) handleBatchConfig(
 			return nil
 		}
 		st.isKeyper = true
+		pubKey := st.config.GetValidatorPublicKey()
 		err := queries.ScheduleShutterMessage(
 			ctx,
-			"check-in",
+			fmt.Sprintf("check-in (validator-pub-key=%s)", hex.EncodeToString(pubKey)),
 			shmsg.NewCheckIn(
-				st.config.GetValidatorPublicKey(),
+				pubKey,
 				&st.config.GetEncryptionKey().PublicKey,
 			),
 		)
@@ -362,7 +364,7 @@ func (st *ShuttermintState) startPhase1Dealing(
 	dkg.markDirty()
 	err = queries.ScheduleShutterMessage(
 		ctx,
-		fmt.Sprintf("poly commitment, eon=%d", eon),
+		fmt.Sprintf("poly commitment (eon=%d)", eon),
 		shmsg.NewPolyCommitment(eon, commitment.Gammas),
 	)
 	if err != nil {
@@ -394,7 +396,7 @@ func (st *ShuttermintState) startPhase2Accusing(
 		}
 		err := queries.ScheduleShutterMessage(
 			ctx,
-			fmt.Sprintf("accusations, eon=%d, count=%d", eon, len(accusations)),
+			fmt.Sprintf("accusations (eon=%d, count=%d)", eon, len(accusations)),
 			shmsg.NewAccusation(eon, accused),
 		)
 		if err != nil {
@@ -423,7 +425,7 @@ func (st *ShuttermintState) startPhase3Apologizing(
 
 		err := queries.ScheduleShutterMessage(
 			ctx,
-			fmt.Sprintf("apologies, eon=%d, count=%d", eon, len(apologies)),
+			fmt.Sprintf("apologies (eon=%d, count=%d)", eon, len(apologies)),
 			shmsg.NewApology(eon, accusers, polyEvals),
 		)
 		if err != nil {
@@ -485,7 +487,7 @@ func (st *ShuttermintState) finalizeDKG(
 
 	err = queries.ScheduleShutterMessage(
 		ctx,
-		"reporting DKG result",
+		fmt.Sprintf("reporting DKG result (eon=%d)", dkgresult.Eon),
 		dkgresultmsg,
 	)
 	if err != nil {
@@ -737,6 +739,7 @@ func (st *ShuttermintState) HandleEvent(
 	ctx context.Context, queries *kprdb.Queries, event shutterevents.IEvent,
 ) error {
 	var err error
+	log.Info().Str("event", event.String()).Msg("handle shuttermint event")
 	switch e := event.(type) {
 	case *shutterevents.CheckIn:
 		err = st.handleCheckIn(ctx, queries, e)

rolling-shutter/snapshotkeyper/snapshotkeyper.go

@@ -3,6 +3,7 @@ package snapshotkeyper
 
 import (
 	"context"
+	"fmt"
 	"time"
 
 	"github.com/ethereum/go-ethereum/ethclient"
@@ -139,7 +140,7 @@ func (snkpr *snapshotkeyper) handleContractEvents(ctx context.Context) error {
 }
 
 func (snkpr *snapshotkeyper) handleOnChainChanges(ctx context.Context, tx pgx.Tx, l1BlockNumber uint64) error {
-	log.Info().Uint64("l1-block-number", l1BlockNumber).Msg("handle on chain changes")
+	log.Debug().Uint64("l1-block-number", l1BlockNumber).Msg("handle on chain changes")
 	err := snkpr.handleOnChainKeyperSetChanges(ctx, tx, l1BlockNumber)
 	if err != nil {
 		return err
@@ -179,7 +180,11 @@ func (snkpr *snapshotkeyper) sendNewBlockSeen(
 	}
 
 	blockSeenMsg := shmsg.NewBlockSeen(l1BlockNumber)
-	err = q.ScheduleShutterMessage(ctx, "block seen", blockSeenMsg)
+	err = q.ScheduleShutterMessage(
+		ctx,
+		fmt.Sprintf("block seen (block=%d)", l1BlockNumber),
+		blockSeenMsg,
+	)
 	if err != nil {
 		return err
 	}
@@ -253,7 +258,12 @@ func (snkpr *snapshotkeyper) handleOnChainKeyperSetChanges(ctx context.Context,
 		uint64(keyperSet.Threshold),
 		uint64(keyperSet.KeyperConfigIndex),
 	)
-	err = q.ScheduleShutterMessage(ctx, "new batch config", batchConfigMsg)
+	err = q.ScheduleShutterMessage(
+		ctx,
+		fmt.Sprintf("new batch config (activation-block-number=%d, config-index=%d)",
+			keyperSet.ActivationBlockNumber, keyperSet.KeyperConfigIndex),
+		batchConfigMsg,
+	)
 	if err != nil {
 		return err
 	}