hare3: output detailed statistics for session after every iteration (#…

…5220)

this needs to be turned on by {"hare3": "logs-stats": true} as it will add a bit of additional computation.
log level for hare3 should be set atleast to info.

example

```json
{
    "lid": 8,
    "iter": 0,
    "threshold": 401,
    "preround": [
        {
            "grade": 1,
            "tallies": [
                {
                    "total": 796,
                    "valid": 796,
                    "id": "a8577e03ad"
                }
            ]
        },
        {
            "grade": 2,
            "tallies": [
                {
                    "total": 796,
                    "valid": 796,
                    "id": "a8577e03ad"
                }
            ]
        },
        {
            "grade": 3,
            "tallies": [
                {
                    "total": 796,
                    "valid": 796,
                    "id": "a8577e03ad"
                }
            ]
        },
        {
            "grade": 4,
            "tallies": [
                {
                    "total": 796,
                    "valid": 796,
                    "id": "a8577e03ad"
                }
            ]
        },
        {
            "grade": 5,
            "tallies": [
                {
                    "total": 796,
                    "valid": 796,
                    "id": "a8577e03ad"
                }
            ]
        }
    ],
    "propose": [
        {
            "ref": "9a65a38f9d",
            "grade": 2,
            "proposals": [
                "a8577e03ad"
            ]
        }
    ],
    "commit": [
        {
            "grade": 4,
            "tallies": [
                {
                    "total": 787,
                    "valid": 787,
                    "id": "9a65a38f9d"
                }
            ]
        },
        {
            "grade": 5,
            "tallies": [
                {
                    "total": 787,
                    "valid": 787,
                    "id": "9a65a38f9d"
                }
            ]
        }
    ],
    "notify": [
        {
            "grade": 5,
            "tallies": [
                {
                    "total": 788,
                    "valid": 788,
                    "id": "9a65a38f9d"
                }
            ]
        }
    ]
}
```

common/types/atxid_list_test.go

@@ -19,7 +19,7 @@ func TestATXIDList_Hash(t *testing.T) {
 		{
 			name:     "Case 1",
 			atxList:  ATXIDList{ATXID(CalcHash32([]byte("1")))},
-			expected: "0x3c462dd7363d6e6fb7d5085679d2ee7de30f2d939722882be0816387983051f6",
+			expected: "3c462dd736",
 		},
 	}
 

common/types/hashes.go

@@ -194,7 +194,7 @@ func (h Hash32) Hex() string { return util.Encode(h[:]) }
 // String implements the stringer interface and is used also by the logger when
 // doing full logging into a file.
 func (h Hash32) String() string {
-	return h.Hex()
+	return h.ShortString()
 }
 
 // ShortString returns the first 5 characters of the hash, for logging purposes.

hare3/hare.go

@@ -40,7 +40,10 @@ type Config struct {
 	IterationsLimit uint8         `mapstructure:"iterations-limit"`
 	PreroundDelay   time.Duration `mapstructure:"preround-delay"`
 	RoundDuration   time.Duration `mapstructure:"round-duration"`
-	ProtocolName    string
+	// LogStats if true will log iteration statistics with INFO level at the start of the next iteration.
+	// This requires additional computation and should be used for debugging only.
+	LogStats     bool `mapstructure:"log-stats"`
+	ProtocolName string
 }
 
 func (cfg *Config) Validate(zdist time.Duration) error {
@@ -64,6 +67,7 @@ func (cfg *Config) MarshalLogObject(encoder zapcore.ObjectEncoder) error {
 	encoder.AddUint8("iterations limit", cfg.IterationsLimit)
 	encoder.AddDuration("preround delay", cfg.PreroundDelay)
 	encoder.AddDuration("round duration", cfg.RoundDuration)
+	encoder.AddBool("log stats", cfg.LogStats)
 	encoder.AddString("p2p protocol", cfg.ProtocolName)
 	return nil
 }
@@ -438,6 +442,11 @@ func (h *Hare) run(session *session) error {
 			if err := h.onOutput(session, current, out); err != nil {
 				return err
 			}
+			// we are logginng stats 1 network delay after new iteration start
+			// so that we can receive notify messages from previous iteration
+			if session.proto.Round == softlock && h.config.LogStats {
+				h.log.Info("stats", zap.Uint32("lid", session.lid.Uint32()), zap.Inline(session.proto.Stats()))
+			}
 			if out.terminated {
 				if !result {
 					return fmt.Errorf("terminated without result")

hare3/hare_test.go

@@ -550,11 +550,13 @@ func (*testTracer) OnMessageReceived(*Message) {}
 
 func testHare(t *testing.T, active, inactive, equivocators int, opts ...clusterOpt) {
 	t.Parallel()
+	cfg := DefaultConfig()
+	cfg.LogStats = true
 	tst := &tester{
 		TB:            t,
 		rng:           rand.New(rand.NewSource(1001)),
 		start:         time.Now(),
-		cfg:           DefaultConfig(),
+		cfg:           cfg,
 		layerDuration: 5 * time.Minute,
 		beacon:        types.Beacon{1, 1, 1, 1},
 		genesis:       types.GetEffectiveGenesis(),