Merge pull request #955 from iotaledger/feat/import-export-logs

Better Snapshot Import/Export debug logs

pkg/model/account_diff.go

@@ -6,6 +6,7 @@ import (
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/lo"
 	"github.com/iotaledger/hive.go/serializer/v2/stream"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -74,6 +75,26 @@ func (d *AccountDiff) Clone() *AccountDiff {
 	}
 }
 
+func (d *AccountDiff) String() string {
+	builder := stringify.NewStructBuilder("AccountDiff")
+	builder.AddField(stringify.NewStructField("BICChange", int64(d.BICChange)))
+	builder.AddField(stringify.NewStructField("PreviousUpdatedSlot", uint32(d.PreviousUpdatedSlot)))
+	builder.AddField(stringify.NewStructField("NewExpirySlot", uint32(d.NewExpirySlot)))
+	builder.AddField(stringify.NewStructField("PreviousExpirySlot", uint32(d.PreviousExpirySlot)))
+	builder.AddField(stringify.NewStructField("NewOutputID", d.NewOutputID))
+	builder.AddField(stringify.NewStructField("PreviousOutputID", d.PreviousOutputID))
+	builder.AddField(stringify.NewStructField("BlockIssuerKeysAdded", d.BlockIssuerKeysAdded))
+	builder.AddField(stringify.NewStructField("BlockIssuerKeysRemoved", d.BlockIssuerKeysRemoved))
+	builder.AddField(stringify.NewStructField("ValidatorStakeChange", d.ValidatorStakeChange))
+	builder.AddField(stringify.NewStructField("DelegationStakeChange", d.DelegationStakeChange))
+	builder.AddField(stringify.NewStructField("FixedCostChange", d.FixedCostChange))
+	builder.AddField(stringify.NewStructField("StakeEndEpochChange", d.StakeEndEpochChange))
+	builder.AddField(stringify.NewStructField("NewLatestSupportedVersionAndHash", d.NewLatestSupportedVersionAndHash))
+	builder.AddField(stringify.NewStructField("PrevLatestSupportedVersionAndHash", d.PrevLatestSupportedVersionAndHash))
+
+	return builder.String()
+}
+
 func (d *AccountDiff) Bytes() ([]byte, error) {
 	byteBuffer := stream.NewByteBuffer()
 

pkg/model/poolstats.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/serializer/v2/stream"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -59,6 +60,14 @@ func (p *PoolsStats) Bytes() ([]byte, error) {
 	return byteBuffer.Bytes()
 }
 
+func (p *PoolsStats) String() string {
+	return stringify.Struct("PoolsStats",
+		stringify.NewStructField("TotalStake", uint64(p.TotalStake)),
+		stringify.NewStructField("TotalValidatorStake", uint64(p.TotalValidatorStake)),
+		stringify.NewStructField("ProfitMargin", p.ProfitMargin),
+	)
+}
+
 type PoolRewards struct {
 	// Total stake of the validator including delegations
 	PoolStake iotago.BaseToken
@@ -111,3 +120,11 @@ func (p *PoolRewards) Bytes() ([]byte, error) {
 
 	return byteBuffer.Bytes()
 }
+
+func (p *PoolRewards) String() string {
+	return stringify.Struct("PoolRewards",
+		stringify.NewStructField("PoolStake", uint64(p.PoolStake)),
+		stringify.NewStructField("PoolRewards", uint64(p.PoolRewards)),
+		stringify.NewStructField("FixedCost", uint64(p.FixedCost)),
+	)
+}

pkg/model/signaled_block.go

@@ -5,6 +5,7 @@ import (
 	"time"
 
 	"github.com/iotaledger/hive.go/lo"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -60,3 +61,12 @@ func SignaledBlockFromBytesFunc(decodeAPI iotago.API) func([]byte) (*SignaledBlo
 		return signaledBlock, consumedBytes, nil
 	}
 }
+
+func (s *SignaledBlock) String() string {
+	return stringify.Struct("SignaledBlock",
+		stringify.NewStructField("ID", s.ID),
+		stringify.NewStructField("IssuingTime", s.IssuingTime),
+		stringify.NewStructField("HighestSupportedVersion", s.HighestSupportedVersion),
+		stringify.NewStructField("ProtocolParametersHash", s.ProtocolParametersHash),
+	)
+}

pkg/model/validator_performance.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/serializer/v2/stream"
+	"github.com/iotaledger/hive.go/stringify"
 )
 
 type ValidatorPerformance struct {
@@ -66,3 +67,11 @@ func (p *ValidatorPerformance) Bytes() ([]byte, error) {
 
 	return byteBuffer.Bytes()
 }
+
+func (p *ValidatorPerformance) String() string {
+	return stringify.Struct("ValidatorPerformance",
+		stringify.NewStructField("SlotActivityVector", p.SlotActivityVector),
+		stringify.NewStructField("BlocksIssuedCount", p.BlocksIssuedCount),
+		stringify.NewStructField("HighestSupportedVersionAndHash", p.HighestSupportedVersionAndHash),
+	)
+}

pkg/model/version_and_hash.go

@@ -4,6 +4,7 @@ import (
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/lo"
 	"github.com/iotaledger/hive.go/serializer/v2/byteutils"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -32,3 +33,10 @@ func VersionAndHashFromBytes(bytes []byte) (VersionAndHash, int, error) {
 
 	return VersionAndHash{version, hash}, versionBytesConsumed + hashBytesConsumed, nil
 }
+
+func (v VersionAndHash) String() string {
+	return stringify.Struct("VersionAndHash",
+		stringify.NewStructField("Version", byte(v.Version)),
+		stringify.NewStructField("Hash", v.Hash),
+	)
+}

pkg/protocol/engine/accounts/accounts.go

@@ -6,6 +6,7 @@ import (
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/runtime/options"
 	"github.com/iotaledger/hive.go/serializer/v2/stream"
+	"github.com/iotaledger/hive.go/stringify"
 	"github.com/iotaledger/iota-core/pkg/model"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
@@ -165,6 +166,21 @@ func (a *AccountData) Bytes() ([]byte, error) {
 	return byteBuffer.Bytes()
 }
 
+func (a *AccountData) String() string {
+	return stringify.Struct("AccountData",
+		stringify.NewStructField("ID", a.ID),
+		stringify.NewStructField("Credits", a.Credits),
+		stringify.NewStructField("ExpirySlot", uint32(a.ExpirySlot)),
+		stringify.NewStructField("OutputID", a.OutputID),
+		stringify.NewStructField("BlockIssuerKeys", a.BlockIssuerKeys),
+		stringify.NewStructField("ValidatorStake", uint64(a.ValidatorStake)),
+		stringify.NewStructField("DelegationStake", uint64(a.DelegationStake)),
+		stringify.NewStructField("FixedCost", uint64(a.FixedCost)),
+		stringify.NewStructField("StakeEndEpoch", uint64(a.StakeEndEpoch)),
+		stringify.NewStructField("LatestSupportedProtocolVersionAndHash", a.LatestSupportedProtocolVersionAndHash),
+	)
+}
+
 func WithCredits(credits *BlockIssuanceCredits) options.Option[AccountData] {
 	return func(a *AccountData) {
 		a.Credits = credits

pkg/protocol/engine/accounts/accountsledger/snapshot.go

@@ -27,7 +27,7 @@ func (m *Manager) Import(reader io.ReadSeeker) error {
 			return ierrors.Wrapf(err, "unable to set account %s", accountData.ID)
 		}
 
-		m.LogDebug("Imported account", "accountID", accountData.ID, "outputID", accountData.OutputID, "credits.value", accountData.Credits.Value, "credits.updateSlot", accountData.Credits.UpdateSlot)
+		m.LogDebug("Imported account", "accountData", accountData)
 
 		return nil
 	}); err != nil {
@@ -189,6 +189,8 @@ func (m *Manager) readSlotDiffs(reader io.ReadSeeker) error {
 				accountDiff = model.NewAccountDiff()
 			}
 
+			m.LogDebug("Imported account diff", "slot", slot, "accountID", accountID, "destroyed", destroyed, "accountDiff", accountDiff)
+
 			if err := diffStore.Store(accountID, accountDiff, destroyed); err != nil {
 				return ierrors.Wrapf(err, "unable to store slot diff for accountID %s", accountID)
 			}
@@ -250,6 +252,8 @@ func (m *Manager) writeSlotDiffs(writer io.WriteSeeker, targetSlot iotago.SlotIn
 					}
 				}
 
+				m.LogDebug("Exported account diff", "slot", slot, "accountID", accountID, "destroyed", destroyed, "accountDiff", accountDiff)
+
 				accountsInDiffCount++
 
 				return true

pkg/protocol/engine/accounts/credits.go

@@ -4,6 +4,7 @@ import (
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/serializer/v2"
 	"github.com/iotaledger/hive.go/serializer/v2/stream"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -23,6 +24,13 @@ func NewBlockIssuanceCredits(value iotago.BlockIssuanceCredits, updateTime iotag
 	}
 }
 
+func (c *BlockIssuanceCredits) String() string {
+	return stringify.Struct("BlockIssuanceCredits",
+		stringify.NewStructField("Value", int64(c.Value)),
+		stringify.NewStructField("UpdateSlot", uint32(c.UpdateSlot)),
+	)
+}
+
 // Bytes returns a serialized version of the Credits.
 func (c *BlockIssuanceCredits) Bytes() ([]byte, error) {
 	byteBuffer := stream.NewByteBuffer()

pkg/protocol/engine/accounts/mana.go

@@ -2,6 +2,7 @@ package accounts
 
 import (
 	"github.com/iotaledger/hive.go/runtime/syncutils"
+	"github.com/iotaledger/hive.go/stringify"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
 
@@ -42,3 +43,14 @@ func (m *Mana) UpdateTime() iotago.SlotIndex {
 
 	return m.updateTime
 }
+
+func (m *Mana) String() string {
+	m.mutex.RLock()
+	defer m.mutex.RUnlock()
+
+	return stringify.Struct("Mana",
+		stringify.NewStructField("Value", uint64(m.value)),
+		stringify.NewStructField("ExcessBaseTokens", uint64(m.excessBaseTokens)),
+		stringify.NewStructField("UpdateTime", uint32(m.updateTime)),
+	)
+}

pkg/protocol/engine/engine.go

@@ -253,6 +253,18 @@ func New(
 			e.InitializedEvent().Trigger()
 
 			e.LogTrace("initialized", "settings", e.Storage.Settings().String())
+
+			latestCommitment := e.Storage.Settings().LatestCommitment()
+			e.LogInfo("LatestCommitment", "slot", latestCommitment.Slot(), "ID", latestCommitment.ID())
+			e.LogInfo("Ledger state", "AccountRoot", e.Ledger.AccountRoot(), "latestCommitment.Slot", latestCommitment.Slot())
+
+			currentEpoch := e.CommittedAPI().TimeProvider().EpochFromSlot(latestCommitment.Slot())
+			e.LogInfo("Rewards state", "RewardsRoot", lo.PanicOnErr(e.SybilProtection.RewardsRoot(currentEpoch)), "epoch", currentEpoch, "latestCommitment.Slot", latestCommitment.Slot())
+
+			if currentEpoch > 0 {
+				prevEpoch := currentEpoch - 1
+				e.LogInfo("Rewards state", "RewardsRoot", lo.PanicOnErr(e.SybilProtection.RewardsRoot(prevEpoch)), "epoch", prevEpoch, "lastSlot", e.CommittedAPI().TimeProvider().EpochEnd(prevEpoch))
+			}
 		},
 	)
 }

pkg/protocol/engine/ledger/ledger.go

@@ -43,6 +43,8 @@ type Ledger interface {
 	Export(writer io.WriteSeeker, targetSlot iotago.SlotIndex) error
 	TrackBlock(block *blocks.Block)
 
+	AccountRoot() iotago.Identifier
+
 	// Reset resets the component to a clean state as if it was created at the last commitment.
 	Reset()
 

pkg/protocol/engine/ledger/ledger/ledger.go

@@ -221,6 +221,10 @@ func (l *Ledger) CommitSlot(slot iotago.SlotIndex) (stateRoot iotago.Identifier,
 	return stateTreeRoot, stateDiff.Mutations().Root(), l.accountsLedger.AccountsTreeRoot(), outputs, spenders, mutations, nil
 }
 
+func (l *Ledger) AccountRoot() iotago.Identifier {
+	return l.accountsLedger.AccountsTreeRoot()
+}
+
 func (l *Ledger) AddAccount(output *utxoledger.Output, blockIssuanceCredits iotago.BlockIssuanceCredits) error {
 	return l.accountsLedger.AddAccount(output, blockIssuanceCredits)
 }

pkg/protocol/sybilprotection/sybilprotection.go

@@ -39,5 +39,7 @@ type SybilProtection interface {
 	// Reset resets the component to a clean state as if it was created at the last commitment.
 	Reset()
 
+	RewardsRoot(epoch iotago.EpochIndex) (rewardsRoot iotago.Identifier, err error)
+
 	module.Module
 }

pkg/protocol/sybilprotection/sybilprotectionv1/performance/rewards.go

@@ -1,10 +1,13 @@
 package performance
 
 import (
+	"fmt"
+
 	"github.com/iotaledger/hive.go/ads"
 	"github.com/iotaledger/hive.go/core/safemath"
 	"github.com/iotaledger/hive.go/ierrors"
 	"github.com/iotaledger/hive.go/lo"
+	"github.com/iotaledger/hive.go/stringify"
 	"github.com/iotaledger/iota-core/pkg/model"
 	iotago "github.com/iotaledger/iota.go/v4"
 )
@@ -18,7 +21,23 @@ func (t *Tracker) RewardsRoot(epoch iotago.EpochIndex) (iotago.Identifier, error
 		return iotago.Identifier{}, err
 	}
 
-	return m.Root(), nil
+	root := m.Root()
+
+	builder := stringify.NewStructBuilder("RewardsRoot")
+	builder.AddField(stringify.NewStructField("Root", root))
+	builder.AddField(stringify.NewStructField("WasRestoredFromStorage", m.WasRestoredFromStorage()))
+
+	if err := m.Stream(func(accountID iotago.AccountID, poolRewards *model.PoolRewards) error {
+		builder.AddField(stringify.NewStructField(fmt.Sprintf("account[%s]", accountID.String()), poolRewards))
+
+		return nil
+	}); err != nil {
+		panic(err)
+	}
+
+	t.LogDebug("RewardsRoot", "epoch", epoch, "rewardsMap", builder)
+
+	return root, nil
 }
 
 func (t *Tracker) ValidatorReward(validatorID iotago.AccountID, stakingFeature *iotago.StakingFeature, claimingEpoch iotago.EpochIndex) (validatorReward iotago.Mana, firstRewardEpoch iotago.EpochIndex, lastRewardEpoch iotago.EpochIndex, err error) {